2025-12-03 11:16:21.843904 | Job console starting...
2025-12-03 11:16:22.363205 | Updating repositories
2025-12-03 11:16:23.185891 | Preparing job workspace
2025-12-03 11:16:41.177672 | Running Ansible setup...
2025-12-03 11:16:48.442965 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-03 11:16:51.519502 | 
2025-12-03 11:16:51.519637 | PLAY [localhost]
2025-12-03 11:16:51.559832 | 
2025-12-03 11:16:51.559959 | TASK [Gathering Facts]
2025-12-03 11:16:55.244621 | localhost | ok
2025-12-03 11:16:55.264676 | 
2025-12-03 11:16:55.270266 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-03 11:16:56.706499 | localhost -> localhost | changed
2025-12-03 11:16:56.711969 | 
2025-12-03 11:16:56.712062 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-03 11:16:58.628110 | localhost -> localhost | changed
2025-12-03 11:16:58.636854 | 
2025-12-03 11:16:58.636939 | TASK [Setup log path fact]
2025-12-03 11:16:58.680935 | localhost | ok
2025-12-03 11:16:58.739810 | 
2025-12-03 11:16:58.739922 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-03 11:16:58.820888 | localhost | ok
2025-12-03 11:16:58.828360 | 
2025-12-03 11:16:58.828429 | TASK [emit-job-header : Print job information]
2025-12-03 11:16:58.941438 | # Job Information
2025-12-03 11:16:58.941584 | Ansible Version: 2.15.12
2025-12-03 11:16:58.941616 | Job: cifmw-molecule-nat64_appliance
2025-12-03 11:16:58.941641 | Pipeline: github-check
2025-12-03 11:16:58.941662 | Executor: ibm-bm3-ze.softwarefactory-project.io
2025-12-03 11:16:58.941682 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3451
2025-12-03 11:16:58.941724 | Log URL (when completed): https://logserver.rdoproject.org/87e/rdoproject.org/87ee27cfd709496cb8700cb94fbe5297/
2025-12-03 11:16:58.941748 | Event ID: 4ab514e0-d039-11f0-81e0-fb882bdc02c6
2025-12-03 11:16:58.945753 | 
2025-12-03 11:16:58.945823 | LOOP [emit-job-header : Print node information]
2025-12-03 11:16:59.295018 | localhost | ok:
2025-12-03 11:16:59.295216 | localhost | # Node Information
2025-12-03 11:16:59.295247 | localhost | Inventory Hostname: controller
2025-12-03 11:16:59.295273 | localhost | Hostname: np0005543739
2025-12-03 11:16:59.295294 | localhost | Username: zuul
2025-12-03 11:16:59.295316 | localhost | Distro: CentOS 9
2025-12-03 11:16:59.295351 | localhost | Provider: ibm-bm3-nodepool
2025-12-03 11:16:59.295372 | localhost | Region: regionOne
2025-12-03 11:16:59.295391 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-12-03 11:16:59.295411 | localhost | Product Name: OpenStack Compute
2025-12-03 11:16:59.295429 | localhost | Interface IP: 192.168.25.211
2025-12-03 11:16:59.357670 | 
2025-12-03 11:16:59.357781 | PLAY [all]
2025-12-03 11:16:59.382748 | 
2025-12-03 11:16:59.384794 | TASK [Gather network facts]
2025-12-03 11:16:59.833368 | controller | ok
2025-12-03 11:16:59.898499 | 
2025-12-03 11:16:59.898586 | TASK [include_role : start-zuul-console]
2025-12-03 11:16:59.957490 | controller | ok
2025-12-03 11:16:59.973630 | 
2025-12-03 11:16:59.973729 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-03 11:17:00.709714 | controller | ok
2025-12-03 11:17:00.745628 | 
2025-12-03 11:17:00.747045 | TASK [include_role : add-build-sshkey]
2025-12-03 11:17:00.836270 | controller | ok
2025-12-03 11:17:00.864319 | 
2025-12-03 11:17:00.864420 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-03 11:17:01.719200 | controller -> localhost | ok
2025-12-03 11:17:01.724945 | 
2025-12-03 11:17:01.725096 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-03 11:17:01.807953 | controller | ok
2025-12-03 11:17:01.831558 | controller | included: /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-03 11:17:01.855733 | 
2025-12-03 11:17:01.855814 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-03 11:17:04.238247 | controller -> localhost | Generating public/private rsa key pair.
2025-12-03 11:17:04.238471 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/87ee27cfd709496cb8700cb94fbe5297_id_rsa.
2025-12-03 11:17:04.238508 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/87ee27cfd709496cb8700cb94fbe5297_id_rsa.pub.
2025-12-03 11:17:04.238533 | controller -> localhost | The key fingerprint is:
2025-12-03 11:17:04.238555 | controller -> localhost | SHA256:2JLxfiAZhVJYjnOzBbib7Jojl5VtFTnq2TCtHLeJ/rY zuul-build-sshkey
2025-12-03 11:17:04.238575 | controller -> localhost | The key's randomart image is:
2025-12-03 11:17:04.238596 | controller -> localhost | +---[RSA 3072]----+
2025-12-03 11:17:04.238615 | controller -> localhost | |     =+...       |
2025-12-03 11:17:04.238634 | controller -> localhost | |    +o.o+        |
2025-12-03 11:17:04.238652 | controller -> localhost | |    oo*o.o       |
2025-12-03 11:17:04.238682 | controller -> localhost | |    .o=%+        |
2025-12-03 11:17:04.238722 | controller -> localhost | |   . BB@So       |
2025-12-03 11:17:04.238744 | controller -> localhost | |    * O++.       |
2025-12-03 11:17:04.238762 | controller -> localhost | |   + o  . .      |
2025-12-03 11:17:04.238783 | controller -> localhost | |. +.. . ..       |
2025-12-03 11:17:04.238802 | controller -> localhost | | ooo   oE.       |
2025-12-03 11:17:04.238820 | controller -> localhost | +----[SHA256]-----+
2025-12-03 11:17:04.238868 | controller -> localhost | ok: Runtime: 0:00:00.720916
2025-12-03 11:17:04.251135 | 
2025-12-03 11:17:04.251202 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-03 11:17:04.381956 | controller | ok
2025-12-03 11:17:04.409222 | controller | included: /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-03 11:17:04.479092 | 
2025-12-03 11:17:04.479176 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-03 11:17:04.552296 | controller | skipping: Conditional result was False
2025-12-03 11:17:04.557646 | 
2025-12-03 11:17:04.557776 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-03 11:17:05.532760 | controller | changed
2025-12-03 11:17:05.550230 | 
2025-12-03 11:17:05.550321 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-03 11:17:05.895256 | controller | ok
2025-12-03 11:17:05.904687 | 
2025-12-03 11:17:05.904779 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-03 11:17:06.999228 | controller | changed
2025-12-03 11:17:07.023451 | 
2025-12-03 11:17:07.023532 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-03 11:17:08.056398 | controller | changed
2025-12-03 11:17:08.066674 | 
2025-12-03 11:17:08.066788 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-03 11:17:08.144037 | controller | skipping: Conditional result was False
2025-12-03 11:17:08.153089 | 
2025-12-03 11:17:08.153172 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-03 11:17:09.428841 | controller -> localhost | changed
2025-12-03 11:17:09.440266 | 
2025-12-03 11:17:09.440345 | TASK [add-build-sshkey : Add back temp key]
2025-12-03 11:17:10.372791 | controller -> localhost | Identity added: /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/87ee27cfd709496cb8700cb94fbe5297_id_rsa (zuul-build-sshkey)
2025-12-03 11:17:10.373048 | controller -> localhost | ok: Runtime: 0:00:00.046846
2025-12-03 11:17:10.379154 | 
2025-12-03 11:17:10.379231 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-03 11:17:10.946682 | controller | ok
2025-12-03 11:17:10.951318 | 
2025-12-03 11:17:10.951391 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-03 11:17:11.068723 | controller | skipping: Conditional result was False
2025-12-03 11:17:11.086192 | 
2025-12-03 11:17:11.086278 | TASK [include_role : validate-host]
2025-12-03 11:17:11.165117 | controller | ok
2025-12-03 11:17:11.238776 | 
2025-12-03 11:17:11.238903 | TASK [validate-host : Define zuul_info_dir fact]
2025-12-03 11:17:11.343421 | controller | ok
2025-12-03 11:17:11.351788 | 
2025-12-03 11:17:11.351889 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-12-03 11:17:12.303234 | controller -> localhost | ok
2025-12-03 11:17:12.309140 | 
2025-12-03 11:17:12.309204 | TASK [validate-host : Collect information about the host]
2025-12-03 11:17:13.030367 | controller | ok
2025-12-03 11:17:13.059312 | 
2025-12-03 11:17:13.059410 | TASK [validate-host : Sanitize hostname]
2025-12-03 11:17:13.259027 | controller | ok
2025-12-03 11:17:13.266004 | 
2025-12-03 11:17:13.266087 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-12-03 11:17:14.637597 | controller -> localhost | changed
2025-12-03 11:17:14.642920 | 
2025-12-03 11:17:14.642999 | TASK [validate-host : Collect information about zuul worker]
2025-12-03 11:17:15.582593 | controller | ok
2025-12-03 11:17:15.587524 | 
2025-12-03 11:17:15.587592 | TASK [validate-host : Write out all zuul information for each host]
2025-12-03 11:17:17.051435 | controller -> localhost | changed
2025-12-03 11:17:17.069073 | 
2025-12-03 11:17:17.069165 | TASK [include_role : prepare-workspace-openshift]
2025-12-03 11:17:17.157985 | controller | skipping: Conditional result was False
2025-12-03 11:17:17.163930 | 
2025-12-03 11:17:17.164013 | TASK [include_role : remove-zuul-sshkey]
2025-12-03 11:17:17.228309 | controller | skipping: Conditional result was False
2025-12-03 11:17:17.238270 | 
2025-12-03 11:17:17.238362 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-03 11:17:17.481643 | controller | ok: "logs"
2025-12-03 11:17:17.482433 | controller | ok: All items complete
2025-12-03 11:17:17.482473 | 
2025-12-03 11:17:17.660094 | controller | ok: "artifacts"
2025-12-03 11:17:17.876531 | controller | ok: "docs"
2025-12-03 11:17:17.891131 | 
2025-12-03 11:17:17.891212 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-03 11:17:18.140174 | controller | changed: "logs"
2025-12-03 11:17:18.359540 | controller | changed: "artifacts"
2025-12-03 11:17:18.546347 | controller | changed: "docs"
2025-12-03 11:17:18.627152 | 
2025-12-03 11:17:18.627224 | PLAY RECAP
2025-12-03 11:17:18.627270 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-12-03 11:17:18.627300 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-03 11:17:18.627320 | 
2025-12-03 11:17:18.912372 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-03 11:17:18.913100 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-12-03 11:17:21.727065 | 
2025-12-03 11:17:21.727179 | PLAY [all]
2025-12-03 11:17:21.833475 | 
2025-12-03 11:17:21.833593 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-12-03 11:17:22.072952 | controller | ok
2025-12-03 11:17:22.077933 | 
2025-12-03 11:17:22.078017 | TASK [mirror-info-fork : Create /etc/ci]
2025-12-03 11:17:23.145195 | controller | changed
2025-12-03 11:17:23.161830 | 
2025-12-03 11:17:23.161915 | TASK [mirror-info-fork : Install ci_mirror script]
2025-12-03 11:17:25.434953 | controller | changed
2025-12-03 11:17:25.467124 | 
2025-12-03 11:17:25.467256 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-12-03 11:17:26.454091 | controller | changed:
2025-12-03 11:17:26.454286 | controller | {
2025-12-03 11:17:26.454322 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-12-03 11:17:26.454369 | controller | }
2025-12-03 11:17:26.689377 | controller | changed:
2025-12-03 11:17:26.689572 | controller | {
2025-12-03 11:17:26.689617 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-12-03 11:17:26.689643 | controller | }
2025-12-03 11:17:26.934056 | controller | changed:
2025-12-03 11:17:26.934747 | controller | {
2025-12-03 11:17:26.934800 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-12-03 11:17:26.934828 | controller | }
2025-12-03 11:17:27.185909 | controller | changed:
2025-12-03 11:17:27.185990 | controller | {
2025-12-03 11:17:27.186036 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-12-03 11:17:27.186060 | controller | }
2025-12-03 11:17:27.431289 | controller | changed:
2025-12-03 11:17:27.431377 | controller | {
2025-12-03 11:17:27.431407 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-12-03 11:17:27.431429 | controller | }
2025-12-03 11:17:27.656713 | controller | changed:
2025-12-03 11:17:27.656800 | controller | {
2025-12-03 11:17:27.656829 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-12-03 11:17:27.656853 | controller | }
2025-12-03 11:17:27.882307 | controller | changed:
2025-12-03 11:17:27.882407 | controller | {
2025-12-03 11:17:27.882443 | 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-12-03 11:17:27.882471 | controller | }
2025-12-03 11:17:28.116926 | controller | changed:
2025-12-03 11:17:28.117011 | controller | {
2025-12-03 11:17:28.117041 | 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-12-03 11:17:28.117065 | controller | }
2025-12-03 11:17:28.355342 | controller | changed:
2025-12-03 11:17:28.355432 | controller | {
2025-12-03 11:17:28.355461 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-12-03 11:17:28.355484 | controller | }
2025-12-03 11:17:28.603469 | controller | changed:
2025-12-03 11:17:28.603549 | controller | {
2025-12-03 11:17:28.603579 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-12-03 11:17:28.603600 | controller | }
2025-12-03 11:17:28.840572 | controller | changed:
2025-12-03 11:17:28.840660 | controller | {
2025-12-03 11:17:28.840687 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-12-03 11:17:28.840730 | controller | }
2025-12-03 11:17:29.092404 | controller | changed:
2025-12-03 11:17:29.092504 | controller | {
2025-12-03 11:17:29.092543 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-12-03 11:17:29.092578 | controller | }
2025-12-03 11:17:29.382481 | controller | changed:
2025-12-03 11:17:29.382572 | controller | {
2025-12-03 11:17:29.382600 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-12-03 11:17:29.382622 | controller | }
2025-12-03 11:17:29.622293 | controller | changed:
2025-12-03 11:17:29.622384 | controller | {
2025-12-03 11:17:29.622412 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-12-03 11:17:29.622434 | controller | }
2025-12-03 11:17:29.864226 | controller | changed:
2025-12-03 11:17:29.864305 | controller | {
2025-12-03 11:17:29.864343 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-12-03 11:17:29.864366 | controller | }
2025-12-03 11:17:30.097045 | controller | changed:
2025-12-03 11:17:30.097155 | controller | {
2025-12-03 11:17:30.097183 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-12-03 11:17:30.097204 | controller | }
2025-12-03 11:17:30.340856 | controller | changed:
2025-12-03 11:17:30.340953 | controller | {
2025-12-03 11:17:30.340984 | 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-12-03 11:17:30.341008 | controller | }
2025-12-03 11:17:30.573430 | controller | changed:
2025-12-03 11:17:30.573522 | controller | {
2025-12-03 11:17:30.573552 | 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-12-03 11:17:30.573583 | controller | }
2025-12-03 11:17:30.814067 | controller | changed:
2025-12-03 11:17:30.814156 | controller | {
2025-12-03 11:17:30.814184 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-12-03 11:17:30.814205 | controller | }
2025-12-03 11:17:31.064451 | controller | changed:
2025-12-03 11:17:31.064533 | controller | {
2025-12-03 11:17:31.064562 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-12-03 11:17:31.064585 | controller | }
2025-12-03 11:17:31.290775 | controller | changed:
2025-12-03 11:17:31.290871 | controller | {
2025-12-03 11:17:31.290899 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-12-03 11:17:31.290919 | controller | }
2025-12-03 11:17:31.527810 | controller | changed:
2025-12-03 11:17:31.527893 | controller | {
2025-12-03 11:17:31.530532 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-12-03 11:17:31.530583 | controller | }
2025-12-03 11:17:31.771482 | controller | changed:
2025-12-03 11:17:31.771562 | controller | {
2025-12-03 11:17:31.771589 | 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-12-03 11:17:31.771613 | controller | }
2025-12-03 11:17:32.014257 | controller | changed:
2025-12-03 11:17:32.014360 | controller | {
2025-12-03 11:17:32.014391 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-12-03 11:17:32.014414 | controller | }
2025-12-03 11:17:32.244810 | controller | changed:
2025-12-03 11:17:32.244884 | controller | {
2025-12-03 11:17:32.244981 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-12-03 11:17:32.245007 | controller | }
2025-12-03 11:17:32.460983 | controller | changed:
2025-12-03 11:17:32.461063 | controller | {
2025-12-03 11:17:32.461091 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-12-03 11:17:32.461113 | controller | }
2025-12-03 11:17:32.483489 | 
2025-12-03 11:17:32.483585 | TASK [Set timezone to UTC]
2025-12-03 11:17:32.976919 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-12-03 11:17:32.983042 | 
2025-12-03 11:17:32.983168 | TASK [Create nodepool directory]
2025-12-03 11:17:33.257785 | controller | changed
2025-12-03 11:17:33.264192 | 
2025-12-03 11:17:33.264269 | TASK [Create nodepool sub_nodes file]
2025-12-03 11:17:34.002794 | controller | changed
2025-12-03 11:17:34.008732 | 
2025-12-03 11:17:34.008818 | TASK [Create nodepool sub_nodes_private file]
2025-12-03 11:17:34.723368 | controller | changed
2025-12-03 11:17:34.733776 | 
2025-12-03 11:17:34.733842 | LOOP [Populate nodepool sub_nodes file]
2025-12-03 11:17:34.796887 | 
2025-12-03 11:17:34.797042 | LOOP [Populate nodepool sub_nodes_private file]
2025-12-03 11:17:34.876052 | 
2025-12-03 11:17:34.876223 | TASK [Create nodepool primary file]
2025-12-03 11:17:34.923119 | controller | skipping: Conditional result was False
2025-12-03 11:17:34.929418 | 
2025-12-03 11:17:34.929512 | TASK [Create nodepool node_private for this node]
2025-12-03 11:17:35.640825 | controller | changed
2025-12-03 11:17:35.650037 | 
2025-12-03 11:17:35.650101 | LOOP [Copy ssh keys to nodepool directory]
2025-12-03 11:17:36.358690 | controller | ok: Item: id_rsa Runtime: 0:00:00.004472
2025-12-03 11:17:36.360116 | 
2025-12-03 11:17:36.561030 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.004146
2025-12-03 11:17:36.571379 | 
2025-12-03 11:17:36.571735 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-12-03 11:17:37.353038 | controller | changed
2025-12-03 11:17:37.361217 | 
2025-12-03 11:17:37.361296 | TASK [Validate sudoers config after edits]
2025-12-03 11:17:37.721701 | controller | /etc/sudoers: parsed OK
2025-12-03 11:17:37.721761 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-12-03 11:17:37.721770 | controller | /etc/sudoers.d/zuul: parsed OK
2025-12-03 11:17:37.721831 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-12-03 11:17:37.944933 | controller | ok: Runtime: 0:00:00.006031
2025-12-03 11:17:37.950664 | 
2025-12-03 11:17:37.950773 | TASK [Show the environment passed in to job shell scripts]
2025-12-03 11:17:38.245471 | controller | SHELL=/bin/bash
2025-12-03 11:17:38.245519 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-12-03 11:17:38.245530 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-12-03 11:17:38.245537 | controller | ZUUL_CHANGES=rdo-jobs:master:refs/changes/88/58488/1^openstack-k8s-operators/ci-framework:main:refs/changes/51/3451/2261ed433b240c3ce81443dcd27657d36bfed699
2025-12-03 11:17:38.245544 | controller | PWD=/home/zuul
2025-12-03 11:17:38.245549 | controller | ZUUL_PIPELINE=github-check
2025-12-03 11:17:38.245555 | controller | LOGNAME=zuul
2025-12-03 11:17:38.245560 | controller | XDG_SESSION_TYPE=tty
2025-12-03 11:17:38.245605 | controller | _=/usr/bin/env
2025-12-03 11:17:38.245615 | controller | MOTD_SHOWN=pam
2025-12-03 11:17:38.245620 | controller | HOME=/home/zuul
2025-12-03 11:17:38.245625 | controller | LANG=en_US.UTF-8
2025-12-03 11:17:38.245650 | controller | SSH_CONNECTION=192.168.25.12 55318 192.168.25.211 22
2025-12-03 11:17:38.245656 | 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-12-03 11:17:38.245663 | controller | ZUUL_CHANGE_IDS=58488,1 3451,2261ed433b240c3ce81443dcd27657d36bfed699
2025-12-03 11:17:38.245669 | controller | WORKSPACE=/home/zuul/workspace
2025-12-03 11:17:38.245674 | controller | XDG_SESSION_CLASS=user
2025-12-03 11:17:38.245679 | controller | SELINUX_ROLE_REQUESTED=
2025-12-03 11:17:38.245684 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-12-03 11:17:38.245690 | controller | USER=zuul
2025-12-03 11:17:38.245695 | controller | ZUUL_VOTING=True
2025-12-03 11:17:38.245700 | controller | BUILD_TIMEOUT=1800000
2025-12-03 11:17:38.245706 | controller | SELINUX_USE_CURRENT_RANGE=
2025-12-03 11:17:38.245711 | controller | SHLVL=1
2025-12-03 11:17:38.245716 | controller | ZUUL_PATCHSET=2261ed433b240c3ce81443dcd27657d36bfed699
2025-12-03 11:17:38.245721 | controller | XDG_SESSION_ID=1
2025-12-03 11:17:38.245727 | controller | ZUUL_BRANCH=main
2025-12-03 11:17:38.245732 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-12-03 11:17:38.245737 | controller | SSH_CLIENT=192.168.25.12 55318 22
2025-12-03 11:17:38.245744 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-12-03 11:17:38.245749 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-12-03 11:17:38.245755 | controller | which_declare=declare -f
2025-12-03 11:17:38.245760 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-12-03 11:17:38.245766 | controller | SELINUX_LEVEL_REQUESTED=
2025-12-03 11:17:38.245771 | controller | ZUUL_CHANGE=3451
2025-12-03 11:17:38.245776 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-12-03 11:17:38.245782 | controller | ZUUL_UUID=87ee27cfd709496cb8700cb94fbe5297
2025-12-03 11:17:38.245787 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-12-03 11:17:38.245792 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-12-03 11:17:38.245798 | controller | }
2025-12-03 11:17:38.522075 | controller | ok: Runtime: 0:00:00.006268
2025-12-03 11:17:38.528246 | 
2025-12-03 11:17:38.528347 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-12-03 11:17:38.572497 | controller | skipping: Conditional result was False
2025-12-03 11:17:38.578524 | 
2025-12-03 11:17:38.578594 | TASK [Symlink /home/zuul-worker/workspace]
2025-12-03 11:17:39.200236 | controller | skipping: Conditional result was False
2025-12-03 11:17:39.207064 | 
2025-12-03 11:17:39.207158 | TASK [Ensure legacy workspace directory]
2025-12-03 11:17:39.504845 | controller | changed
2025-12-03 11:17:39.548229 | 
2025-12-03 11:17:39.548312 | PLAY RECAP
2025-12-03 11:17:39.548371 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-12-03 11:17:39.548398 | 
2025-12-03 11:17:39.937397 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-12-03 11:17:39.938158 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-12-03 11:17:41.768649 | 
2025-12-03 11:17:41.768784 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-12-03 11:17:41.808588 | 
2025-12-03 11:17:41.808729 | TASK [Create zuul-output directory]
2025-12-03 11:17:42.245882 | controller | changed
2025-12-03 11:17:42.253114 | 
2025-12-03 11:17:42.253196 | TASK [Slurp Zuul inventory test]
2025-12-03 11:17:42.775680 | controller -> localhost | ok
2025-12-03 11:17:42.782965 | 
2025-12-03 11:17:42.783063 | TASK [Save zuul inventory]
2025-12-03 11:17:43.872904 | controller | changed
2025-12-03 11:17:43.885765 | 
2025-12-03 11:17:43.885841 | TASK [Save zuul vars without the change_message]
2025-12-03 11:17:44.707032 | controller | changed
2025-12-03 11:17:44.771964 | 
2025-12-03 11:17:44.772071 | PLAY RECAP
2025-12-03 11:17:44.772137 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-03 11:17:44.772163 | 
2025-12-03 11:17:45.013741 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-12-03 11:17:45.014485 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-12-03 11:17:46.049400 | 
2025-12-03 11:17:46.049508 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-12-03 11:17:46.075934 | 
2025-12-03 11:17:46.076013 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-12-03 11:17:46.108527 | controller | ok
2025-12-03 11:17:46.136130 | 
2025-12-03 11:17:46.136254 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-12-03 11:17:46.213074 | controller | skipping: Conditional result was False
2025-12-03 11:17:46.219587 | 
2025-12-03 11:17:46.219660 | TASK [mirror-info-fork : Create /etc/ci]
2025-12-03 11:17:46.748663 | controller | ok
2025-12-03 11:17:46.758199 | 
2025-12-03 11:17:46.758272 | TASK [mirror-info-fork : Install ci_mirror script]
2025-12-03 11:17:47.672355 | controller | ok
2025-12-03 11:17:47.700035 | 
2025-12-03 11:17:47.700113 | TASK [Prepare workspace]
2025-12-03 11:17:47.753386 | controller | ok
2025-12-03 11:17:47.794516 | 
2025-12-03 11:17:47.794620 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-03 11:17:48.229168 | controller | ok
2025-12-03 11:17:48.238641 | 
2025-12-03 11:17:48.239477 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-03 11:17:51.661250 | controller | Output suppressed because no_log was given
2025-12-03 11:17:51.674913 | 
2025-12-03 11:17:51.675026 | LOOP [Create zuul-output directory]
2025-12-03 11:17:51.882245 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-12-03 11:17:52.058847 | controller | ok: "/home/zuul/zuul-output/logs"
2025-12-03 11:17:52.075139 | 
2025-12-03 11:17:52.075245 | TASK [Install required packages]
2025-12-03 11:18:51.681224 | controller | changed
2025-12-03 11:18:51.686763 | 
2025-12-03 11:18:51.686827 | TASK [Install venv]
2025-12-03 11:19:56.387079 | controller | changed
2025-12-03 11:19:56.435310 | 
2025-12-03 11:19:56.435404 | PLAY RECAP
2025-12-03 11:19:56.435445 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-12-03 11:19:56.435468 | 
2025-12-03 11:19:56.502611 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-12-03 11:19:56.503496 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-12-03 11:19:57.043976 | 
2025-12-03 11:19:57.044075 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-12-03 11:19:57.065464 | 
2025-12-03 11:19:57.065545 | TASK [Gather required facts]
2025-12-03 11:19:57.561566 | controller | ok
2025-12-03 11:19:57.570477 | 
2025-12-03 11:19:57.570584 | TASK [Load environment var if instructed to]
2025-12-03 11:19:57.595169 | controller | skipping: Conditional result was False
2025-12-03 11:19:57.600507 | 
2025-12-03 11:19:57.600583 | TASK [Ensure group_vars dir exists]
2025-12-03 11:19:57.912502 | controller | ok
2025-12-03 11:19:57.918739 | 
2025-12-03 11:19:57.918825 | TASK [Print related variables]
2025-12-03 11:19:57.948117 | controller | ok:
2025-12-03 11:19:57.948564 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2025-12-03 11:19:57.948618 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/nat64_appliance
2025-12-03 11:19:57.954124 | 
2025-12-03 11:19:57.954200 | TASK [Run molecule]
2025-12-03 11:19:58.927051 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-12-03 11:19:58.997535 | controller | INFO     Performing prerun with role_name_check=0...
2025-12-03 11:20:17.022208 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.022719 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.023236 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.023709 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.024201 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+2261ed43 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+2261ed43 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.024661 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.025117 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.025568 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.026023 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.026470 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.026923 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.027393 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.027844 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.028292 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.028768 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-03 11:20:17.038155 | controller | INFO     Running default > prepare
2025-12-03 11:20:17.718264 | controller |
2025-12-03 11:20:17.718321 | controller | PLAY [Prepare] *****************************************************************
2025-12-03 11:20:17.718350 | controller |
2025-12-03 11:20:17.718470 | controller | TASK [Gathering Facts] *********************************************************
2025-12-03 11:20:17.718574 | controller | Wednesday 03 December 2025  11:20:17 +0000 (0:00:00.019)       0:00:00.019 ****
2025-12-03 11:20:18.542593 | controller | ok: [instance]
2025-12-03 11:20:18.542657 | controller |
2025-12-03 11:20:18.542748 | controller | TASK [Create custom basedir] ***************************************************
2025-12-03 11:20:18.542850 | controller | Wednesday 03 December 2025  11:20:18 +0000 (0:00:00.825)       0:00:00.844 ****
2025-12-03 11:20:18.842563 | controller | ok: [instance]
2025-12-03 11:20:18.842670 | controller |
2025-12-03 11:20:18.842778 | controller | TASK [Install some debug utils] ************************************************
2025-12-03 11:20:18.842878 | controller | Wednesday 03 December 2025  11:20:18 +0000 (0:00:00.299)       0:00:01.144 ****
2025-12-03 11:20:23.324626 | controller | changed: [instance]
2025-12-03 11:20:23.324727 | controller |
2025-12-03 11:20:23.324843 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-12-03 11:20:23.324957 | controller | Wednesday 03 December 2025  11:20:23 +0000 (0:00:04.482)       0:00:05.626 ****
2025-12-03 11:20:23.342757 | controller | skipping: [instance]
2025-12-03 11:20:23.342864 | controller |
2025-12-03 11:20:23.342987 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-12-03 11:20:23.343110 | controller | Wednesday 03 December 2025  11:20:23 +0000 (0:00:00.018)       0:00:05.645 ****
2025-12-03 11:20:23.384145 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-12-03 11:20:23.384256 | controller |
2025-12-03 11:20:23.384363 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-12-03 11:20:23.384467 | controller | Wednesday 03 December 2025  11:20:23 +0000 (0:00:00.041)       0:00:05.686 ****
2025-12-03 11:20:23.663164 | controller | ok: [instance]
2025-12-03 11:20:23.663258 | controller |
2025-12-03 11:20:23.663374 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-12-03 11:20:23.663482 | controller | Wednesday 03 December 2025  11:20:23 +0000 (0:00:00.278)       0:00:05.965 ****
2025-12-03 11:20:23.876225 | controller | ok: [instance]
2025-12-03 11:20:23.876306 | controller |
2025-12-03 11:20:23.876416 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-12-03 11:20:23.876525 | controller | Wednesday 03 December 2025  11:20:23 +0000 (0:00:00.212)       0:00:06.178 ****
2025-12-03 11:20:24.539225 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-12-03 11:20:24.539763 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-12-03 11:20:24.599024 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-12-03 11:20:24.599051 | controller |
2025-12-03 11:20:24.599061 | controller | TASK [Deploy repo-setup] *******************************************************
2025-12-03 11:20:24.599069 | controller | Wednesday 03 December 2025  11:20:24 +0000 (0:00:00.663)       0:00:06.841 ****
2025-12-03 11:20:24.599080 | controller |
2025-12-03 11:20:25.105407 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-12-03 11:20:25.105436 | controller | Wednesday 03 December 2025  11:20:24 +0000 (0:00:00.059)       0:00:06.901 ****
2025-12-03 11:20:25.105452 | controller | changed: [instance] => (item=tmp)
2025-12-03 11:20:25.768249 | controller | changed: [instance] => (item=artifacts/repositories)
2025-12-03 11:20:25.768278 | controller | changed: [instance] => (item=venv/repo_setup)
2025-12-03 11:20:25.768286 | controller |
2025-12-03 11:20:25.768298 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-12-03 11:20:25.768305 | controller | Wednesday 03 December 2025  11:20:25 +0000 (0:00:00.505)       0:00:07.407 ****
2025-12-03 11:20:25.768314 | controller | ok: [instance]
2025-12-03 11:20:26.843077 | controller |
2025-12-03 11:20:26.843124 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-12-03 11:20:26.843133 | controller | Wednesday 03 December 2025  11:20:25 +0000 (0:00:00.662)       0:00:08.070 ****
2025-12-03 11:20:26.843143 | controller | changed: [instance]
2025-12-03 11:20:34.791522 | controller |
2025-12-03 11:20:34.791556 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-12-03 11:20:34.791565 | controller | Wednesday 03 December 2025  11:20:26 +0000 (0:00:01.074)       0:00:09.144 ****
2025-12-03 11:20:34.791575 | controller | changed: [instance]
2025-12-03 11:20:35.491048 | controller |
2025-12-03 11:20:35.491089 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-12-03 11:20:35.491098 | controller | Wednesday 03 December 2025  11:20:34 +0000 (0:00:07.948)       0:00:17.093 ****
2025-12-03 11:20:35.491108 | controller | changed: [instance]
2025-12-03 11:20:35.513074 | controller |
2025-12-03 11:20:35.513104 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-12-03 11:20:35.513113 | controller | Wednesday 03 December 2025  11:20:35 +0000 (0:00:00.699)       0:00:17.792 ****
2025-12-03 11:20:35.513123 | controller | skipping: [instance]
2025-12-03 11:20:36.294144 | controller |
2025-12-03 11:20:36.294173 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-12-03 11:20:36.294182 | controller | Wednesday 03 December 2025  11:20:35 +0000 (0:00:00.022)       0:00:17.815 ****
2025-12-03 11:20:36.294192 | controller | changed: [instance]
2025-12-03 11:20:36.330271 | controller |
2025-12-03 11:20:36.330297 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-12-03 11:20:36.330305 | controller | Wednesday 03 December 2025  11:20:36 +0000 (0:00:00.780)       0:00:18.595 ****
2025-12-03 11:20:36.330316 | controller | skipping: [instance]
2025-12-03 11:20:36.364695 | controller |
2025-12-03 11:20:36.364726 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-12-03 11:20:36.364735 | controller | Wednesday 03 December 2025  11:20:36 +0000 (0:00:00.036)       0:00:18.632 ****
2025-12-03 11:20:36.364745 | controller | skipping: [instance]
2025-12-03 11:20:36.364763 | controller |
2025-12-03 11:20:36.364844 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-12-03 11:20:36.364957 | controller | Wednesday 03 December 2025  11:20:36 +0000 (0:00:00.034)       0:00:18.667 ****
2025-12-03 11:20:36.399321 | controller | skipping: [instance]
2025-12-03 11:20:36.925258 | controller |
2025-12-03 11:20:36.925287 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-12-03 11:20:36.925296 | controller | Wednesday 03 December 2025  11:20:36 +0000 (0:00:00.034)       0:00:18.701 ****
2025-12-03 11:20:36.925306 | controller | changed: [instance]
2025-12-03 11:20:37.369642 | controller |
2025-12-03 11:20:37.369673 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-12-03 11:20:37.369682 | controller | Wednesday 03 December 2025  11:20:36 +0000 (0:00:00.525)       0:00:19.227 ****
2025-12-03 11:20:37.369695 | controller | changed: [instance]
2025-12-03 11:20:37.398727 | controller |
2025-12-03 11:20:37.398760 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-12-03 11:20:37.398769 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.444)       0:00:19.671 ****
2025-12-03 11:20:37.398779 | controller | skipping: [instance]
2025-12-03 11:20:37.426730 | controller |
2025-12-03 11:20:37.426752 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-12-03 11:20:37.426762 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.028)       0:00:19.700 ****
2025-12-03 11:20:37.426773 | controller | skipping: [instance]
2025-12-03 11:20:37.426801 | controller |
2025-12-03 11:20:37.426811 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-12-03 11:20:37.426982 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.028)       0:00:19.728 ****
2025-12-03 11:20:37.454747 | controller | skipping: [instance]
2025-12-03 11:20:37.454771 | controller |
2025-12-03 11:20:37.454780 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-12-03 11:20:37.454791 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.027)       0:00:19.756 ****
2025-12-03 11:20:37.491455 | controller | ok: [instance]
2025-12-03 11:20:37.518860 | controller |
2025-12-03 11:20:37.518883 | controller | TASK [repo_setup : Create download directory] **********************************
2025-12-03 11:20:37.518891 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.036)       0:00:19.793 ****
2025-12-03 11:20:37.518901 | controller | skipping: [instance]
2025-12-03 11:20:37.545666 | controller |
2025-12-03 11:20:37.545688 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-12-03 11:20:37.545696 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.027)       0:00:19.821 ****
2025-12-03 11:20:37.545706 | controller | skipping: [instance]
2025-12-03 11:20:37.572355 | controller |
2025-12-03 11:20:37.572374 | controller | TASK [Download the RPM] ********************************************************
2025-12-03 11:20:37.572381 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.026)       0:00:19.847 ****
2025-12-03 11:20:37.572390 | controller | skipping: [instance]
2025-12-03 11:20:37.601262 | controller |
2025-12-03 11:20:37.601280 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-12-03 11:20:37.601288 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.026)       0:00:19.874 ****
2025-12-03 11:20:37.601297 | controller | skipping: [instance]
2025-12-03 11:20:37.627705 | controller |
2025-12-03 11:20:37.627730 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-12-03 11:20:37.627740 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.028)       0:00:19.903 ****
2025-12-03 11:20:37.627751 | controller | skipping: [instance]
2025-12-03 11:20:37.627780 | controller |
2025-12-03 11:20:37.627946 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-12-03 11:20:37.656498 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.026)       0:00:19.930 ****
2025-12-03 11:20:37.656520 | controller | skipping: [instance]
2025-12-03 11:20:37.682695 | controller |
2025-12-03 11:20:37.682722 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-12-03 11:20:37.682732 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.028)       0:00:19.958 ****
2025-12-03 11:20:37.682744 | controller | skipping: [instance]
2025-12-03 11:20:37.868719 | controller |
2025-12-03 11:20:37.868750 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-12-03 11:20:37.868759 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.026)       0:00:19.984 ****
2025-12-03 11:20:37.868769 | controller | ok: [instance]
2025-12-03 11:20:37.869040 | controller |
2025-12-03 11:20:38.077894 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-12-03 11:20:38.077924 | controller | Wednesday 03 December 2025  11:20:37 +0000 (0:00:00.186)       0:00:20.170 ****
2025-12-03 11:20:38.077936 | controller | changed: [instance]
2025-12-03 11:20:38.298399 | controller |
2025-12-03 11:20:38.298426 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-12-03 11:20:38.298434 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.208)       0:00:20.379 ****
2025-12-03 11:20:38.298445 | controller | changed: [instance]
2025-12-03 11:20:38.319747 | controller |
2025-12-03 11:20:38.319792 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-12-03 11:20:38.319803 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.220)       0:00:20.600 ****
2025-12-03 11:20:38.319816 | controller | skipping: [instance]
2025-12-03 11:20:38.319841 | controller |
2025-12-03 11:20:38.319909 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-12-03 11:20:38.320028 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.021)       0:00:20.622 ****
2025-12-03 11:20:38.342839 | controller | skipping: [instance]
2025-12-03 11:20:38.364644 | controller |
2025-12-03 11:20:38.364669 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-12-03 11:20:38.364680 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.022)       0:00:20.644 ****
2025-12-03 11:20:38.364691 | controller | skipping: [instance]
2025-12-03 11:20:38.386077 | controller |
2025-12-03 11:20:38.386098 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-12-03 11:20:38.386112 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.021)       0:00:20.666 ****
2025-12-03 11:20:38.386121 | controller | skipping: [instance]
2025-12-03 11:20:38.407616 | controller |
2025-12-03 11:20:38.407654 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-12-03 11:20:38.407665 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.021)       0:00:20.688 ****
2025-12-03 11:20:38.407677 | controller | skipping: [instance]
2025-12-03 11:20:38.428715 | controller |
2025-12-03 11:20:38.428749 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-12-03 11:20:38.428758 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.021)       0:00:20.709 ****
2025-12-03 11:20:38.428769 | controller | skipping: [instance]
2025-12-03 11:20:38.428795 | controller |
2025-12-03 11:20:38.429025 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-12-03 11:20:38.445339 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.021)       0:00:20.731 ****
2025-12-03 11:20:38.445361 | controller | skipping: [instance]
2025-12-03 11:20:38.473434 | controller |
2025-12-03 11:20:38.473454 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-12-03 11:20:38.473461 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.016)       0:00:20.747 ****
2025-12-03 11:20:38.473470 | controller | skipping: [instance]
2025-12-03 11:20:38.490335 | controller |
2025-12-03 11:20:38.490355 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-12-03 11:20:38.490364 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.028)       0:00:20.775 ****
2025-12-03 11:20:38.490375 | controller | skipping: [instance]
2025-12-03 11:20:38.513230 | controller |
2025-12-03 11:20:38.513247 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-12-03 11:20:38.513254 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.016)       0:00:20.792 ****
2025-12-03 11:20:38.513262 | controller | skipping: [instance]
2025-12-03 11:20:38.542383 | controller |
2025-12-03 11:20:38.542400 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-12-03 11:20:38.542407 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.022)       0:00:20.815 ****
2025-12-03 11:20:38.542415 | controller | skipping: [instance]
2025-12-03 11:20:38.571448 | controller |
2025-12-03 11:20:38.571471 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-12-03 11:20:38.571480 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.029)       0:00:20.844 ****
2025-12-03 11:20:38.571491 | controller | skipping: [instance]
2025-12-03 11:20:38.600181 | controller |
2025-12-03 11:20:38.600200 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-12-03 11:20:38.600207 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.028)       0:00:20.873 ****
2025-12-03 11:20:38.600216 | controller | skipping: [instance]
2025-12-03 11:20:38.628725 | controller |
2025-12-03 11:20:38.628758 | controller | TASK [test_deps : Install additional packages] *********************************
2025-12-03 11:20:38.628767 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.028)       0:00:20.902 ****
2025-12-03 11:20:38.628777 | controller | skipping: [instance]
2025-12-03 11:20:38.628803 | controller |
2025-12-03 11:20:38.628810 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-12-03 11:20:38.628817 | controller | Wednesday 03 December 2025  11:20:38 +0000 (0:00:00.028)       0:00:20.931 ****
2025-12-03 11:21:18.118346 | controller | ok: [instance]
2025-12-03 11:21:18.118400 | controller |
2025-12-03 11:21:18.118645 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-12-03 11:21:19.284008 | controller | Wednesday 03 December 2025  11:21:18 +0000 (0:00:39.489)       0:01:00.420 ****
2025-12-03 11:21:19.284045 | controller | ok: [instance]
2025-12-03 11:21:19.316112 | controller |
2025-12-03 11:21:19.316145 | controller | TASK [test_deps : Install extra packages] **************************************
2025-12-03 11:21:19.316154 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:01.165)       0:01:01.585 ****
2025-12-03 11:21:19.316164 | controller | skipping: [instance]
2025-12-03 11:21:19.500716 | controller |
2025-12-03 11:21:19.500747 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-12-03 11:21:19.500756 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.032)       0:01:01.618 ****
2025-12-03 11:21:19.500771 | controller | ok: [instance]
2025-12-03 11:21:19.500868 | controller |
2025-12-03 11:21:19.500880 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-12-03 11:21:19.500889 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.184)       0:01:01.802 ****
2025-12-03 11:21:19.679486 | controller | changed: [instance]
2025-12-03 11:21:19.869435 | controller |
2025-12-03 11:21:19.869467 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-12-03 11:21:19.869475 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.178)       0:01:01.981 ****
2025-12-03 11:21:19.869485 | controller | ok: [instance]
2025-12-03 11:21:19.896555 | controller |
2025-12-03 11:21:19.896587 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-12-03 11:21:19.896595 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.189)       0:01:02.171 ****
2025-12-03 11:21:19.896606 | controller | skipping: [instance]
2025-12-03 11:21:19.912123 | controller |
2025-12-03 11:21:19.912148 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-12-03 11:21:19.912156 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.026)       0:01:02.198 ****
2025-12-03 11:21:19.912166 | controller | skipping: [instance]
2025-12-03 11:21:19.930603 | controller |
2025-12-03 11:21:19.930626 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-12-03 11:21:19.930650 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.016)       0:01:02.214 ****
2025-12-03 11:21:19.930660 | controller | ok: [instance]
2025-12-03 11:21:19.956730 | controller |
2025-12-03 11:21:19.956767 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-12-03 11:21:19.956776 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.018)       0:01:02.232 ****
2025-12-03 11:21:19.956788 | controller | skipping: [instance]
2025-12-03 11:22:37.679966 | controller |
2025-12-03 11:22:37.680002 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-12-03 11:22:37.680011 | controller | Wednesday 03 December 2025  11:21:19 +0000 (0:00:00.025)       0:01:02.258 ****
2025-12-03 11:22:37.680022 | controller | changed: [instance]
2025-12-03 11:22:37.898271 | controller |
2025-12-03 11:22:37.898302 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-12-03 11:22:37.898311 | controller | Wednesday 03 December 2025  11:22:37 +0000 (0:01:17.722)       0:02:19.981 ****
2025-12-03 11:22:37.898320 | controller | changed: [instance]
2025-12-03 11:22:38.277419 | controller |
2025-12-03 11:22:38.277449 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-12-03 11:22:38.277458 | controller | Wednesday 03 December 2025  11:22:37 +0000 (0:00:00.218)       0:02:20.199 ****
2025-12-03 11:22:38.277468 | controller | changed: [instance]
2025-12-03 11:22:38.894709 | controller |
2025-12-03 11:22:38.894803 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-12-03 11:22:38.894813 | controller | Wednesday 03 December 2025  11:22:38 +0000 (0:00:00.379)       0:02:20.579 ****
2025-12-03 11:22:38.894823 | controller | changed: [instance]
2025-12-03 11:22:38.895167 | controller |
2025-12-03 11:22:39.089363 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-12-03 11:22:39.089392 | controller | Wednesday 03 December 2025  11:22:38 +0000 (0:00:00.617)       0:02:21.196 ****
2025-12-03 11:22:39.089404 | controller | ok: [instance]
2025-12-03 11:22:39.791496 | controller |
2025-12-03 11:22:39.791528 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-12-03 11:22:39.791536 | controller | Wednesday 03 December 2025  11:22:39 +0000 (0:00:00.194)       0:02:21.391 ****
2025-12-03 11:22:39.791548 | controller | ok: [instance]
2025-12-03 11:22:40.628729 | controller |
2025-12-03 11:22:40.628771 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-12-03 11:22:40.628780 | controller | Wednesday 03 December 2025  11:22:39 +0000 (0:00:00.702)       0:02:22.093 ****
2025-12-03 11:22:40.628798 | controller | changed: [instance]
2025-12-03 11:22:40.708705 | controller |
2025-12-03 11:22:40.708738 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-12-03 11:22:40.708746 | controller | Wednesday 03 December 2025  11:22:40 +0000 (0:00:00.837)       0:02:22.930 ****
2025-12-03 11:22:40.708783 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-12-03 11:22:40.708803 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-12-03 11:22:40.708812 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-12-03 11:22:40.708925 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-12-03 11:22:40.709033 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-12-03 11:22:40.709143 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-12-03 11:22:40.709247 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-12-03 11:22:40.709343 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-12-03 11:22:40.709435 | controller |
2025-12-03 11:22:40.709538 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-12-03 11:22:40.709705 | controller | Wednesday 03 December 2025  11:22:40 +0000 (0:00:00.080)       0:02:23.011 ****
2025-12-03 11:22:41.044353 | controller | changed: [instance]
2025-12-03 11:22:41.376697 | controller |
2025-12-03 11:22:41.376728 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-12-03 11:22:41.376741 | controller | Wednesday 03 December 2025  11:22:41 +0000 (0:00:00.335)       0:02:23.346 ****
2025-12-03 11:22:41.376752 | controller | changed: [instance]
2025-12-03 11:22:41.377084 | controller |
2025-12-03 11:22:41.718063 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-12-03 11:22:41.718095 | controller | Wednesday 03 December 2025  11:22:41 +0000 (0:00:00.332)       0:02:23.678 ****
2025-12-03 11:22:41.718108 | controller | changed: [instance]
2025-12-03 11:22:42.056071 | controller |
2025-12-03 11:22:42.056102 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-12-03 11:22:42.056111 | controller | Wednesday 03 December 2025  11:22:41 +0000 (0:00:00.341)       0:02:24.019 ****
2025-12-03 11:22:42.056127 | controller | changed: [instance]
2025-12-03 11:22:42.056146 | controller |
2025-12-03 11:22:42.056240 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-12-03 11:22:42.056343 | controller | Wednesday 03 December 2025  11:22:42 +0000 (0:00:00.338)       0:02:24.358 ****
2025-12-03 11:22:42.409235 | controller | changed: [instance]
2025-12-03 11:22:42.767704 | controller |
2025-12-03 11:22:42.767738 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-12-03 11:22:42.767748 | controller | Wednesday 03 December 2025  11:22:42 +0000 (0:00:00.352)       0:02:24.711 ****
2025-12-03 11:22:42.767774 | controller | changed: [instance]
2025-12-03 11:22:42.768243 | controller |
2025-12-03 11:22:43.097405 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-12-03 11:22:43.097435 | controller | Wednesday 03 December 2025  11:22:42 +0000 (0:00:00.358)       0:02:25.070 ****
2025-12-03 11:22:43.097447 | controller | changed: [instance]
2025-12-03 11:22:43.423431 | controller |
2025-12-03 11:22:43.423461 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-12-03 11:22:43.423469 | controller | Wednesday 03 December 2025  11:22:43 +0000 (0:00:00.329)       0:02:25.399 ****
2025-12-03 11:22:43.423479 | controller | changed: [instance]
2025-12-03 11:22:43.748703 | controller |
2025-12-03 11:22:43.748738 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-12-03 11:22:43.748747 | controller | Wednesday 03 December 2025  11:22:43 +0000 (0:00:00.326)       0:02:25.725 ****
2025-12-03 11:22:43.748772 | controller | changed: [instance]
2025-12-03 11:22:44.086451 | controller |
2025-12-03 11:22:44.086481 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-12-03 11:22:44.086489 | controller | Wednesday 03 December 2025  11:22:43 +0000 (0:00:00.325)       0:02:26.050 ****
2025-12-03 11:22:44.086499 | controller | changed: [instance]
2025-12-03 11:22:44.427931 | controller |
2025-12-03 11:22:44.427961 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-12-03 11:22:44.427969 | controller | Wednesday 03 December 2025  11:22:44 +0000 (0:00:00.337)       0:02:26.388 ****
2025-12-03 11:22:44.427979 | controller | changed: [instance]
2025-12-03 11:22:44.757168 | controller |
2025-12-03 11:22:44.757197 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-12-03 11:22:44.757205 | controller | Wednesday 03 December 2025  11:22:44 +0000 (0:00:00.341)       0:02:26.729 ****
2025-12-03 11:22:44.757215 | controller | changed: [instance]
2025-12-03 11:22:45.103708 | controller |
2025-12-03 11:22:45.103737 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-12-03 11:22:45.103757 | controller | Wednesday 03 December 2025  11:22:44 +0000 (0:00:00.329)       0:02:27.059 ****
2025-12-03 11:22:45.103768 | controller | changed: [instance]
2025-12-03 11:22:45.431124 | controller |
2025-12-03 11:22:45.431156 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-12-03 11:22:45.431165 | controller | Wednesday 03 December 2025  11:22:45 +0000 (0:00:00.346)       0:02:27.405 ****
2025-12-03 11:22:45.431175 | controller | changed: [instance]
2025-12-03 11:22:45.753697 | controller |
2025-12-03 11:22:45.753727 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-12-03 11:22:45.753735 | controller | Wednesday 03 December 2025  11:22:45 +0000 (0:00:00.327)       0:02:27.733 ****
2025-12-03 11:22:45.753755 | controller | changed: [instance]
2025-12-03 11:22:45.753931 | controller |
2025-12-03 11:22:45.753949 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-12-03 11:22:46.078442 | controller | Wednesday 03 December 2025  11:22:45 +0000 (0:00:00.322)       0:02:28.055 ****
2025-12-03 11:22:46.078479 | controller | changed: [instance]
2025-12-03 11:22:46.407790 | controller |
2025-12-03 11:22:46.407823 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-12-03 11:22:46.407832 | controller | Wednesday 03 December 2025  11:22:46 +0000 (0:00:00.323)       0:02:28.379 ****
2025-12-03 11:22:46.407848 | controller | changed: [instance]
2025-12-03 11:22:46.740292 | controller |
2025-12-03 11:22:46.740327 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-12-03 11:22:46.740336 | controller | Wednesday 03 December 2025  11:22:46 +0000 (0:00:00.330)       0:02:28.709 ****
2025-12-03 11:22:46.740346 | controller | changed: [instance]
2025-12-03 11:22:47.098597 | controller |
2025-12-03 11:22:47.098650 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-12-03 11:22:47.098663 | controller | Wednesday 03 December 2025  11:22:46 +0000 (0:00:00.332)       0:02:29.042 ****
2025-12-03 11:22:47.098673 | controller | changed: [instance]
2025-12-03 11:22:47.436695 | controller |
2025-12-03 11:22:47.436727 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-12-03 11:22:47.436735 | controller | Wednesday 03 December 2025  11:22:47 +0000 (0:00:00.358)       0:02:29.400 ****
2025-12-03 11:22:47.436757 | controller | changed: [instance]
2025-12-03 11:22:47.768714 | controller |
2025-12-03 11:22:47.768759 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-12-03 11:22:47.768768 | controller | Wednesday 03 December 2025  11:22:47 +0000 (0:00:00.338)       0:02:29.738 ****
2025-12-03 11:22:47.768779 | controller | changed: [instance]
2025-12-03 11:22:48.096943 | controller |
2025-12-03 11:22:48.096975 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-12-03 11:22:48.096983 | controller | Wednesday 03 December 2025  11:22:47 +0000 (0:00:00.331)       0:02:30.070 ****
2025-12-03 11:22:48.097001 | controller | changed: [instance]
2025-12-03 11:22:48.437366 | controller |
2025-12-03 11:22:48.437398 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-12-03 11:22:48.437406 | controller | Wednesday 03 December 2025  11:22:48 +0000 (0:00:00.328)       0:02:30.398 ****
2025-12-03 11:22:48.437417 | controller | changed: [instance]
2025-12-03 11:22:48.760212 | controller |
2025-12-03 11:22:48.760243 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-12-03 11:22:48.760252 | controller | Wednesday 03 December 2025  11:22:48 +0000 (0:00:00.340)       0:02:30.739 ****
2025-12-03 11:22:48.760262 | controller | changed: [instance]
2025-12-03 11:22:48.777715 | controller |
2025-12-03 11:22:48.777757 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-12-03 11:22:48.777766 | controller | Wednesday 03 December 2025  11:22:48 +0000 (0:00:00.322)       0:02:31.062 ****
2025-12-03 11:22:48.777776 | controller | skipping: [instance]
2025-12-03 11:22:48.777863 | controller |
2025-12-03 11:22:48.777888 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-12-03 11:22:48.777903 | controller | Wednesday 03 December 2025  11:22:48 +0000 (0:00:00.017)       0:02:31.079 ****
2025-12-03 11:22:49.066352 | controller | ok: [instance]
2025-12-03 11:22:49.465732 | controller |
2025-12-03 11:22:49.465778 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-12-03 11:22:49.465787 | controller | Wednesday 03 December 2025  11:22:49 +0000 (0:00:00.288)       0:02:31.368 ****
2025-12-03 11:22:49.465797 | controller | changed: [instance]
2025-12-03 11:22:49.466115 | controller |
2025-12-03 11:22:49.765188 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-12-03 11:22:49.765220 | controller | Wednesday 03 December 2025  11:22:49 +0000 (0:00:00.399)       0:02:31.767 ****
2025-12-03 11:22:49.765233 | controller | changed: [instance]
2025-12-03 11:22:50.039112 | controller |
2025-12-03 11:22:50.039149 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-12-03 11:22:50.039157 | controller | Wednesday 03 December 2025  11:22:49 +0000 (0:00:00.299)       0:02:32.066 ****
2025-12-03 11:22:50.039168 | controller | [WARNING]: Reset is not implemented for this connection
2025-12-03 11:22:50.061756 | controller | changed: [instance]
2025-12-03 11:22:50.062697 | controller |
2025-12-03 11:22:50.062724 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-12-03 11:22:50.062770 | controller | Wednesday 03 December 2025  11:22:50 +0000 (0:00:00.269)       0:02:32.336 ****
2025-12-03 11:22:50.062779 | controller |
2025-12-03 11:22:50.062787 | controller | PLAY RECAP *********************************************************************
2025-12-03 11:22:50.062794 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-12-03 11:22:50.062801 | controller |
2025-12-03 11:22:50.062808 | controller | Wednesday 03 December 2025  11:22:50 +0000 (0:00:00.027)       0:02:32.363 ****
2025-12-03 11:22:50.062814 | controller | ===============================================================================
2025-12-03 11:22:50.062821 | controller | libvirt_manager : Install packages required for using KVM -------------- 77.72s
2025-12-03 11:22:50.062830 | controller | test_deps : Install selinux python libs -------------------------------- 39.49s
2025-12-03 11:22:50.062862 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.95s
2025-12-03 11:22:50.064447 | controller | Install some debug utils ------------------------------------------------ 4.48s
2025-12-03 11:22:50.122195 | controller | test_deps : Install python yaml libs ------------------------------------ 1.17s
2025-12-03 11:22:50.122227 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.07s
2025-12-03 11:22:50.122235 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.84s
2025-12-03 11:22:50.122241 | controller | Gathering Facts --------------------------------------------------------- 0.83s
2025-12-03 11:22:50.122246 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.78s
2025-12-03 11:22:50.122252 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.70s
2025-12-03 11:22:50.122257 | controller | repo_setup : Install repo-setup package --------------------------------- 0.70s
2025-12-03 11:22:50.122269 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.66s
2025-12-03 11:22:50.122275 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.66s
2025-12-03 11:22:50.122280 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.62s
2025-12-03 11:22:50.122286 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.53s
2025-12-03 11:22:50.122291 | controller | repo_setup : Ensure directories are present ----------------------------- 0.51s
2025-12-03 11:22:50.122296 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.44s
2025-12-03 11:22:50.122302 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.40s
2025-12-03 11:22:50.122307 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.38s
2025-12-03 11:22:50.122312 | controller | libvirt_manager : Ensure admin socket is enabled for interface. --------- 0.36s
2025-12-03 11:22:50.122324 | controller | INFO     Running default > converge
2025-12-03 11:22:50.546783 | controller |
2025-12-03 11:22:50.547005 | controller | PLAY [Converge] ****************************************************************
2025-12-03 11:22:50.547149 | controller |
2025-12-03 11:22:50.547290 | controller | TASK [Gathering Facts] *********************************************************
2025-12-03 11:22:50.547432 | controller | Wednesday 03 December 2025  11:22:50 +0000 (0:00:00.013)       0:00:00.013 ****
2025-12-03 11:22:51.333849 | controller | ok: [instance]
2025-12-03 11:22:51.708715 | controller |
2025-12-03 11:22:51.708765 | controller | TASK [Crate SSH keypair] *******************************************************
2025-12-03 11:22:51.708774 | controller | Wednesday 03 December 2025  11:22:51 +0000 (0:00:00.787)       0:00:00.800 ****
2025-12-03 11:22:51.708784 | controller | changed: [instance]
2025-12-03 11:22:51.709163 | controller |
2025-12-03 11:22:52.193548 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-12-03 11:22:52.193581 | controller | Wednesday 03 December 2025  11:22:51 +0000 (0:00:00.375)       0:00:01.175 ****
2025-12-03 11:22:52.193593 | controller | changed: [instance]
2025-12-03 11:22:53.153481 | controller |
2025-12-03 11:22:53.153514 | controller | TASK [Restart firewalld.service] ***********************************************
2025-12-03 11:22:53.153522 | controller | Wednesday 03 December 2025  11:22:52 +0000 (0:00:00.484)       0:00:01.659 ****
2025-12-03 11:22:53.153532 | controller | changed: [instance]
2025-12-03 11:22:53.191113 | controller |
2025-12-03 11:22:53.191147 | controller | TASK [Discover latest image] ***************************************************
2025-12-03 11:22:53.191158 | controller | Wednesday 03 December 2025  11:22:53 +0000 (0:00:00.959)       0:00:02.619 ****
2025-12-03 11:22:53.191170 | controller |
2025-12-03 11:22:54.734369 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-12-03 11:22:54.734400 | controller | Wednesday 03 December 2025  11:22:53 +0000 (0:00:00.037)       0:00:02.657 ****
2025-12-03 11:22:54.734417 | controller | changed: [instance]
2025-12-03 11:22:54.758214 | controller |
2025-12-03 11:22:54.758234 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-12-03 11:22:54.758242 | controller | Wednesday 03 December 2025  11:22:54 +0000 (0:00:01.543)       0:00:04.200 ****
2025-12-03 11:22:54.758251 | controller | ok: [instance]
2025-12-03 11:23:14.620713 | controller |
2025-12-03 11:23:14.620746 | controller | TASK [Download latest image] ***************************************************
2025-12-03 11:23:14.620755 | controller | Wednesday 03 December 2025  11:22:54 +0000 (0:00:00.023)       0:00:04.224 ****
2025-12-03 11:23:14.620766 | controller | changed: [instance]
2025-12-03 11:23:14.658016 | controller |
2025-12-03 11:23:14.658047 | controller | TASK [Build nat64 appliance image] *********************************************
2025-12-03 11:23:14.658055 | controller | Wednesday 03 December 2025  11:23:14 +0000 (0:00:19.862)       0:00:24.087 ****
2025-12-03 11:23:14.658064 | controller |
2025-12-03 11:23:15.119712 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-12-03 11:23:15.119752 | controller | Wednesday 03 December 2025  11:23:14 +0000 (0:00:00.037)       0:00:24.124 ****
2025-12-03 11:23:15.119773 | controller | ok: [instance] => (item=artifacts)
2025-12-03 11:23:15.301448 | controller | ok: [instance] => (item=logs)
2025-12-03 11:23:15.301481 | controller |
2025-12-03 11:23:15.301490 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-12-03 11:23:15.301496 | controller | Wednesday 03 December 2025  11:23:15 +0000 (0:00:00.461)       0:00:24.586 ****
2025-12-03 11:23:15.301506 | controller | changed: [instance]
2025-12-03 11:23:19.857695 | controller |
2025-12-03 11:23:19.857733 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-12-03 11:23:19.857742 | controller | Wednesday 03 December 2025  11:23:15 +0000 (0:00:00.181)       0:00:24.767 ****
2025-12-03 11:23:19.857753 | controller | ok: [instance]
2025-12-03 11:23:27.944567 | controller |
2025-12-03 11:23:27.944601 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-12-03 11:23:27.944610 | controller | Wednesday 03 December 2025  11:23:19 +0000 (0:00:04.556)       0:00:29.324 ****
2025-12-03 11:23:27.944621 | controller | changed: [instance]
2025-12-03 11:23:37.678756 | controller |
2025-12-03 11:23:37.678788 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-12-03 11:23:37.678797 | controller | Wednesday 03 December 2025  11:23:27 +0000 (0:00:08.087)       0:00:37.411 ****
2025-12-03 11:23:37.678808 | controller | changed: [instance] => (item=elements/)
2025-12-03 11:23:37.678833 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-12-03 11:23:37.678840 | controller |
2025-12-03 11:23:37.678846 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-12-03 11:23:37.678853 | controller | Wednesday 03 December 2025  11:23:37 +0000 (0:00:09.734)       0:00:47.145 ****
2025-12-03 11:23:38.722567 | controller | changed: [instance]
2025-12-03 11:23:38.722666 | controller |
2025-12-03 11:23:38.722952 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-12-03 11:28:22.262821 | controller | Wednesday 03 December 2025  11:23:38 +0000 (0:00:01.044)       0:00:48.189 ****
2025-12-03 11:28:22.263022 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-12-03 11:28:22.464215 | controller | changed: [instance]
2025-12-03 11:28:22.464245 | controller |
2025-12-03 11:28:22.464253 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-12-03 11:28:22.464266 | controller | Wednesday 03 December 2025  11:28:22 +0000 (0:04:43.539)       0:05:31.729 ****
2025-12-03 11:28:22.464276 | controller | changed: [instance]
2025-12-03 11:28:22.464294 | controller |
2025-12-03 11:28:22.464410 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-12-03 11:28:22.464528 | controller | Wednesday 03 December 2025  11:28:22 +0000 (0:00:00.201)       0:05:31.930 ****
2025-12-03 11:28:29.992694 | controller | changed: [instance]
2025-12-03 11:28:30.039152 | controller |
2025-12-03 11:28:30.039181 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-12-03 11:28:30.039191 | controller | Wednesday 03 December 2025  11:28:29 +0000 (0:00:07.528)       0:05:39.459 ****
2025-12-03 11:28:30.039203 | controller |
2025-12-03 11:28:30.093710 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-12-03 11:28:30.093729 | controller | Wednesday 03 December 2025  11:28:30 +0000 (0:00:00.046)       0:05:39.505 ****
2025-12-03 11:28:30.093740 | controller | ok: [instance]
2025-12-03 11:28:30.862708 | controller |
2025-12-03 11:28:30.862741 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-12-03 11:28:30.862750 | controller | Wednesday 03 December 2025  11:28:30 +0000 (0:00:00.054)       0:05:39.560 ****
2025-12-03 11:28:30.862761 | controller | changed: [instance]
2025-12-03 11:28:31.183803 | controller |
2025-12-03 11:28:31.183836 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-12-03 11:28:31.183850 | controller | Wednesday 03 December 2025  11:28:30 +0000 (0:00:00.768)       0:05:40.329 ****
2025-12-03 11:28:31.183862 | controller | ok: [instance]
2025-12-03 11:28:31.183945 | controller |
2025-12-03 11:28:31.183975 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-12-03 11:28:31.183988 | controller | Wednesday 03 December 2025  11:28:31 +0000 (0:00:00.321)       0:05:40.650 ****
2025-12-03 11:28:31.408249 | controller | ok: [instance]
2025-12-03 11:28:31.632180 | controller |
2025-12-03 11:28:31.632209 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-12-03 11:28:31.632217 | controller | Wednesday 03 December 2025  11:28:31 +0000 (0:00:00.224)       0:05:40.874 ****
2025-12-03 11:28:31.632229 | controller | changed: [instance]
2025-12-03 11:28:31.862867 | controller |
2025-12-03 11:28:31.862900 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-12-03 11:28:31.862908 | controller | Wednesday 03 December 2025  11:28:31 +0000 (0:00:00.223)       0:05:41.098 ****
2025-12-03 11:28:31.862918 | controller | changed: [instance]
2025-12-03 11:28:32.112165 | controller |
2025-12-03 11:28:32.112195 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-12-03 11:28:32.112204 | controller | Wednesday 03 December 2025  11:28:31 +0000 (0:00:00.230)       0:05:41.329 ****
2025-12-03 11:28:32.112215 | controller | ok: [instance]
2025-12-03 11:28:32.340507 | controller |
2025-12-03 11:28:32.340538 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-12-03 11:28:32.340547 | controller | Wednesday 03 December 2025  11:28:32 +0000 (0:00:00.249)       0:05:41.578 ****
2025-12-03 11:28:32.340558 | controller | ok: [instance]
2025-12-03 11:28:32.569828 | controller |
2025-12-03 11:28:32.569858 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-12-03 11:28:32.569867 | controller | Wednesday 03 December 2025  11:28:32 +0000 (0:00:00.228)       0:05:41.807 ****
2025-12-03 11:28:32.569877 | controller | changed: [instance]
2025-12-03 11:28:33.331710 | controller |
2025-12-03 11:28:33.331744 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-12-03 11:28:33.331753 | controller | Wednesday 03 December 2025  11:28:32 +0000 (0:00:00.229)       0:05:42.036 ****
2025-12-03 11:28:33.331764 | controller | changed: [instance] => (item=br-64v6)
2025-12-03 11:28:33.331799 | controller | changed: [instance] => (item=br-64v4)
2025-12-03 11:28:33.332128 | controller |
2025-12-03 11:28:34.184619 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-12-03 11:28:34.184666 | controller | Wednesday 03 December 2025  11:28:33 +0000 (0:00:00.762)       0:05:42.798 ****
2025-12-03 11:28:34.184678 | controller | changed: [instance]
2025-12-03 11:28:34.215571 | controller |
2025-12-03 11:28:34.215595 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-12-03 11:28:34.215603 | controller | Wednesday 03 December 2025  11:28:34 +0000 (0:00:00.852)       0:05:43.651 ****
2025-12-03 11:28:34.215613 | controller | ok: [instance]
2025-12-03 11:28:34.252804 | controller |
2025-12-03 11:28:34.252826 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-12-03 11:28:34.252834 | controller | Wednesday 03 December 2025  11:28:34 +0000 (0:00:00.031)       0:05:43.682 ****
2025-12-03 11:28:34.252844 | controller |
2025-12-03 11:28:34.613374 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-12-03 11:28:34.613415 | controller | Wednesday 03 December 2025  11:28:34 +0000 (0:00:00.036)       0:05:43.718 ****
2025-12-03 11:28:34.613427 | controller | ok: [instance] => (item=artifacts)
2025-12-03 11:28:35.900722 | controller | ok: [instance] => (item=logs)
2025-12-03 11:28:35.900753 | controller |
2025-12-03 11:28:35.900761 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-12-03 11:28:35.900768 | controller | Wednesday 03 December 2025  11:28:34 +0000 (0:00:00.361)       0:05:44.079 ****
2025-12-03 11:28:35.900778 | controller | ok: [instance]
2025-12-03 11:28:35.900802 | controller |
2025-12-03 11:28:35.900810 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-12-03 11:28:35.900951 | controller | Wednesday 03 December 2025  11:28:35 +0000 (0:00:01.287)       0:05:45.367 ****
2025-12-03 11:28:36.086707 | controller | changed: [instance]
2025-12-03 11:28:36.087094 | controller |
2025-12-03 11:28:36.426816 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-12-03 11:28:36.426847 | controller | Wednesday 03 December 2025  11:28:36 +0000 (0:00:00.185)       0:05:45.553 ****
2025-12-03 11:28:36.426859 | controller | changed: [instance]
2025-12-03 11:28:36.817991 | controller |
2025-12-03 11:28:36.818023 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-12-03 11:28:36.818032 | controller | Wednesday 03 December 2025  11:28:36 +0000 (0:00:00.339)       0:05:45.893 ****
2025-12-03 11:28:36.818047 | controller | changed: [instance]
2025-12-03 11:28:37.181277 | controller |
2025-12-03 11:28:37.181308 | controller | TASK [config_drive : Generate network-data] ************************************
2025-12-03 11:28:37.181317 | controller | Wednesday 03 December 2025  11:28:36 +0000 (0:00:00.391)       0:05:46.284 ****
2025-12-03 11:28:37.181327 | controller | changed: [instance]
2025-12-03 11:28:37.354785 | controller |
2025-12-03 11:28:37.354815 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-12-03 11:28:37.354824 | controller | Wednesday 03 December 2025  11:28:37 +0000 (0:00:00.363)       0:05:46.647 ****
2025-12-03 11:28:37.354834 | controller | ok: [instance]
2025-12-03 11:28:37.372332 | controller |
2025-12-03 11:28:37.372356 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-12-03 11:28:37.372366 | controller | Wednesday 03 December 2025  11:28:37 +0000 (0:00:00.173)       0:05:46.821 ****
2025-12-03 11:28:37.372378 | controller | skipping: [instance]
2025-12-03 11:28:37.578441 | controller |
2025-12-03 11:28:37.578471 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-12-03 11:28:37.578480 | controller | Wednesday 03 December 2025  11:28:37 +0000 (0:00:00.017)       0:05:46.838 ****
2025-12-03 11:28:37.578490 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-12-03 11:28:38.671543 | controller | changed: [instance]
2025-12-03 11:28:38.671574 | controller |
2025-12-03 11:28:38.671582 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-12-03 11:28:38.671589 | controller | Wednesday 03 December 2025  11:28:37 +0000 (0:00:00.205)       0:05:47.044 ****
2025-12-03 11:28:38.671599 | controller | changed: [instance]
2025-12-03 11:28:39.239728 | controller |
2025-12-03 11:28:39.239763 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-12-03 11:28:39.239772 | controller | Wednesday 03 December 2025  11:28:38 +0000 (0:00:01.093)       0:05:48.138 ****
2025-12-03 11:28:39.239782 | controller | changed: [instance]
2025-12-03 11:28:39.262695 | controller |
2025-12-03 11:28:39.262720 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-12-03 11:28:39.262729 | controller | Wednesday 03 December 2025  11:28:39 +0000 (0:00:00.568)       0:05:48.706 ****
2025-12-03 11:28:39.262739 | controller | ok: [instance]
2025-12-03 11:28:39.262820 | controller |
2025-12-03 11:28:39.262852 | controller | TASK [Set MAC address facts] ***************************************************
2025-12-03 11:28:39.262864 | controller | Wednesday 03 December 2025  11:28:39 +0000 (0:00:00.023)       0:05:48.729 ****
2025-12-03 11:28:39.303345 | controller | ok: [instance]
2025-12-03 11:28:39.531668 | controller |
2025-12-03 11:28:39.531703 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-12-03 11:28:39.531712 | controller | Wednesday 03 December 2025  11:28:39 +0000 (0:00:00.040)       0:05:48.770 ****
2025-12-03 11:28:39.531723 | controller | changed: [instance]
2025-12-03 11:28:39.797982 | controller |
2025-12-03 11:28:39.798013 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-12-03 11:28:39.798022 | controller | Wednesday 03 December 2025  11:28:39 +0000 (0:00:00.227)       0:05:48.998 ****
2025-12-03 11:28:39.798034 | controller | ok: [instance]
2025-12-03 11:28:40.015495 | controller |
2025-12-03 11:28:40.015522 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-12-03 11:28:40.015530 | controller | Wednesday 03 December 2025  11:28:39 +0000 (0:00:00.266)       0:05:49.264 ****
2025-12-03 11:28:40.015540 | controller | ok: [instance]
2025-12-03 11:28:40.247064 | controller |
2025-12-03 11:28:40.247094 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-12-03 11:28:40.247102 | controller | Wednesday 03 December 2025  11:28:40 +0000 (0:00:00.217)       0:05:49.482 ****
2025-12-03 11:28:40.247113 | controller | changed: [instance]
2025-12-03 11:28:40.584718 | controller |
2025-12-03 11:28:40.584749 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-12-03 11:28:40.584765 | controller | Wednesday 03 December 2025  11:28:40 +0000 (0:00:00.228)       0:05:49.711 ****
2025-12-03 11:28:40.584775 | controller | changed: [instance]
2025-12-03 11:28:41.386089 | controller |
2025-12-03 11:28:41.386119 | controller | TASK [Restart firewalld.service] ***********************************************
2025-12-03 11:28:41.386128 | controller | Wednesday 03 December 2025  11:28:40 +0000 (0:00:00.337)       0:05:50.048 ****
2025-12-03 11:28:41.386138 | controller | changed: [instance]
2025-12-03 11:28:41.416614 | controller |
2025-12-03 11:28:41.416655 | controller | TASK [Generate test node UUID] *************************************************
2025-12-03 11:28:41.416664 | controller | Wednesday 03 December 2025  11:28:41 +0000 (0:00:00.803)       0:05:50.852 ****
2025-12-03 11:28:41.416674 | controller | ok: [instance]
2025-12-03 11:28:49.695837 | controller |
2025-12-03 11:28:49.695869 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-12-03 11:28:49.695883 | controller | Wednesday 03 December 2025  11:28:41 +0000 (0:00:00.030)       0:05:50.883 ****
2025-12-03 11:28:49.695894 | controller | changed: [instance]
2025-12-03 11:28:49.779068 | controller |
2025-12-03 11:28:49.779098 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-12-03 11:28:49.779107 | controller | Wednesday 03 December 2025  11:28:49 +0000 (0:00:08.277)       0:05:59.161 ****
2025-12-03 11:28:49.779118 | controller |
2025-12-03 11:28:50.187575 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-12-03 11:28:50.187608 | controller | Wednesday 03 December 2025  11:28:49 +0000 (0:00:00.081)       0:05:59.242 ****
2025-12-03 11:28:50.187620 | controller | ok: [instance] => (item=artifacts)
2025-12-03 11:28:50.187705 | controller | ok: [instance] => (item=logs)
2025-12-03 11:28:50.187807 | controller |
2025-12-03 11:28:50.187914 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-12-03 11:28:50.188025 | controller | Wednesday 03 December 2025  11:28:50 +0000 (0:00:00.410)       0:05:59.652 ****
2025-12-03 11:28:51.540844 | controller | ok: [instance]
2025-12-03 11:28:51.540893 | controller |
2025-12-03 11:28:51.541006 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-12-03 11:28:51.541107 | controller | Wednesday 03 December 2025  11:28:51 +0000 (0:00:01.354)       0:06:01.007 ****
2025-12-03 11:28:51.758505 | controller | changed: [instance]
2025-12-03 11:28:51.758662 | controller |
2025-12-03 11:28:51.758798 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-12-03 11:28:51.758908 | controller | Wednesday 03 December 2025  11:28:51 +0000 (0:00:00.217)       0:06:01.224 ****
2025-12-03 11:28:52.171853 | controller | changed: [instance]
2025-12-03 11:28:52.546721 | controller |
2025-12-03 11:28:52.546761 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-12-03 11:28:52.546770 | controller | Wednesday 03 December 2025  11:28:52 +0000 (0:00:00.411)       0:06:01.636 ****
2025-12-03 11:28:52.546781 | controller | changed: [instance]
2025-12-03 11:28:52.546800 | controller |
2025-12-03 11:28:52.546807 | controller | TASK [config_drive : Generate network-data] ************************************
2025-12-03 11:28:52.546814 | controller | Wednesday 03 December 2025  11:28:52 +0000 (0:00:00.375)       0:06:02.012 ****
2025-12-03 11:28:52.910864 | controller | changed: [instance]
2025-12-03 11:28:52.910915 | controller |
2025-12-03 11:28:52.911161 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-12-03 11:28:53.112014 | controller | Wednesday 03 December 2025  11:28:52 +0000 (0:00:00.362)       0:06:02.375 ****
2025-12-03 11:28:53.112050 | controller | ok: [instance]
2025-12-03 11:28:53.129222 | controller |
2025-12-03 11:28:53.129247 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-12-03 11:28:53.129255 | controller | Wednesday 03 December 2025  11:28:53 +0000 (0:00:00.203)       0:06:02.578 ****
2025-12-03 11:28:53.129265 | controller | skipping: [instance]
2025-12-03 11:28:53.329727 | controller |
2025-12-03 11:28:53.329774 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-12-03 11:28:53.329785 | controller | Wednesday 03 December 2025  11:28:53 +0000 (0:00:00.017)       0:06:02.596 ****
2025-12-03 11:28:53.329798 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-12-03 11:28:53.329830 | controller | changed: [instance]
2025-12-03 11:28:53.329900 | controller |
2025-12-03 11:28:53.330006 | controller | TASK [Define test-node VM] *****************************************************
2025-12-03 11:28:53.330112 | controller | Wednesday 03 December 2025  11:28:53 +0000 (0:00:00.200)       0:06:02.796 ****
2025-12-03 11:28:53.620320 | controller | changed: [instance]
2025-12-03 11:28:54.104164 | controller |
2025-12-03 11:28:54.104337 | controller | TASK [Start test-node VM] ******************************************************
2025-12-03 11:28:54.104387 | controller | Wednesday 03 December 2025  11:28:53 +0000 (0:00:00.290)       0:06:03.086 ****
2025-12-03 11:28:54.104517 | controller | changed: [instance]
2025-12-03 11:28:54.105863 | controller |
2025-12-03 11:28:54.106043 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-12-03 11:28:54.106058 | controller | Wednesday 03 December 2025  11:28:54 +0000 (0:00:00.483)       0:06:03.570 ****
2025-12-03 11:29:20.818845 | controller | ok: [instance]
2025-12-03 11:29:20.846018 | controller |
2025-12-03 11:29:20.846050 | controller | TASK [Add test node to inventory] **********************************************
2025-12-03 11:29:20.846059 | controller | Wednesday 03 December 2025  11:29:20 +0000 (0:00:26.714)       0:06:30.285 ****
2025-12-03 11:29:20.846069 | controller | changed: [instance]
2025-12-03 11:29:20.870255 | controller |
2025-12-03 11:29:20.870290 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-12-03 11:29:20.870298 | controller | Wednesday 03 December 2025  11:29:20 +0000 (0:00:00.027)       0:06:30.312 ****
2025-12-03 11:29:20.870327 | controller | changed: [instance]
2025-12-03 11:29:20.870347 | controller |
2025-12-03 11:29:20.870464 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-12-03 11:29:20.870569 | controller | Wednesday 03 December 2025  11:29:20 +0000 (0:00:00.024)       0:06:30.337 ****
2025-12-03 11:29:40.918074 | controller | Pausing for 20 seconds
2025-12-03 11:29:47.374409 | controller | ok: [instance]
2025-12-03 11:29:47.374456 | controller |
2025-12-03 11:29:47.374465 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-12-03 11:29:47.374472 | controller | Wednesday 03 December 2025  11:29:40 +0000 (0:00:20.047)       0:06:50.384 ****
2025-12-03 11:29:47.374482 | controller | changed: [instance]
2025-12-03 11:29:48.448165 | controller |
2025-12-03 11:29:48.448198 | controller | TASK [Grab some info from the test node] ***************************************
2025-12-03 11:29:48.448206 | controller | Wednesday 03 December 2025  11:29:47 +0000 (0:00:06.456)       0:06:56.840 ****
2025-12-03 11:29:48.448217 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-12-03 11:29:49.491419 | controller |
2025-12-03 11:29:49.491469 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-12-03 11:29:49.491478 | controller | Wednesday 03 December 2025  11:29:48 +0000 (0:00:01.073)       0:06:57.914 ****
2025-12-03 11:29:49.491489 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-12-03 11:29:50.128379 | controller |
2025-12-03 11:29:50.128430 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-12-03 11:29:50.128439 | controller | Wednesday 03 December 2025  11:29:49 +0000 (0:00:01.043)       0:06:58.957 ****
2025-12-03 11:29:50.128461 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-12-03 11:29:50.677305 | controller |
2025-12-03 11:29:50.677344 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-12-03 11:29:50.677353 | controller | Wednesday 03 December 2025  11:29:50 +0000 (0:00:00.636)       0:06:59.594 ****
2025-12-03 11:29:50.677366 | controller | changed: [instance]
2025-12-03 11:29:51.022761 | controller |
2025-12-03 11:29:51.022792 | controller | TASK [Write test-node info to file] ********************************************
2025-12-03 11:29:51.022801 | controller | Wednesday 03 December 2025  11:29:50 +0000 (0:00:00.548)       0:07:00.143 ****
2025-12-03 11:29:51.022812 | controller | changed: [instance]
2025-12-03 11:29:51.355280 | controller |
2025-12-03 11:29:51.355316 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-12-03 11:29:51.355326 | controller | Wednesday 03 December 2025  11:29:51 +0000 (0:00:00.345)       0:07:00.489 ****
2025-12-03 11:29:51.355338 | controller | changed: [instance]
2025-12-03 11:29:51.686844 | controller |
2025-12-03 11:29:51.686876 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-12-03 11:29:51.686884 | controller | Wednesday 03 December 2025  11:29:51 +0000 (0:00:00.332)       0:07:00.821 ****
2025-12-03 11:29:51.686895 | controller | changed: [instance]
2025-12-03 11:29:52.021103 | controller |
2025-12-03 11:29:52.021135 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-12-03 11:29:52.021144 | controller | Wednesday 03 December 2025  11:29:51 +0000 (0:00:00.331)       0:07:01.153 ****
2025-12-03 11:29:52.021154 | controller | changed: [instance]
2025-12-03 11:29:52.361760 | controller |
2025-12-03 11:29:52.361798 | controller | TASK [Write hypervisor info to file] *******************************************
2025-12-03 11:29:52.361809 | controller | Wednesday 03 December 2025  11:29:52 +0000 (0:00:00.334)       0:07:01.487 ****
2025-12-03 11:29:52.361822 | controller | changed: [instance]
2025-12-03 11:29:52.361845 | controller |
2025-12-03 11:29:52.361855 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-12-03 11:29:54.065166 | controller | Wednesday 03 December 2025  11:29:52 +0000 (0:00:00.340)       0:07:01.828 ****
2025-12-03 11:29:54.065207 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-12-03 11:29:54.065229 | controller |
2025-12-03 11:29:54.065493 | controller | TASK [Debug the ping example.com result] ***************************************
2025-12-03 11:29:54.107610 | controller | Wednesday 03 December 2025  11:29:54 +0000 (0:00:01.703)       0:07:03.531 ****
2025-12-03 11:29:54.107658 | controller | ok: [instance] => (item=0) =>
2025-12-03 11:29:54.108562 | controller |   msg: '0'
2025-12-03 11:29:54.109503 | controller | ok: [instance] => (item=['PING example.com(a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88)) 56 data bytes', '64 bytes from a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88): icmp_seq=1 ttl=45 time=34.1 ms', '64 bytes from a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88): icmp_seq=2 ttl=45 time=34.2 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1002ms', 'rtt min/avg/max/mdev = 34.144/34.174/34.205/0.030 ms']) =>
2025-12-03 11:29:54.109523 | controller |   msg:
2025-12-03 11:29:54.109531 | controller |   - PING example.com(a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88)) 56 data bytes
2025-12-03 11:29:54.109538 | controller |   - '64 bytes from a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88): icmp_seq=1 ttl=45 time=34.1 ms'
2025-12-03 11:29:54.109546 | controller |   - '64 bytes from a23-215-0-136.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:88): icmp_seq=2 ttl=45 time=34.2 ms'
2025-12-03 11:29:54.110504 | controller |   - ''
2025-12-03 11:29:54.110521 | controller |   - '--- example.com ping statistics ---'
2025-12-03 11:29:54.110529 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1002ms
2025-12-03 11:29:54.110536 | controller |   - rtt min/avg/max/mdev = 34.144/34.174/34.205/0.030 ms
2025-12-03 11:29:54.110542 | controller | ok: [instance] => (item=[]) =>
2025-12-03 11:29:54.110548 | controller |   msg: []
2025-12-03 11:29:54.110553 | controller |
2025-12-03 11:29:54.110563 | controller | PLAY RECAP *********************************************************************
2025-12-03 11:29:54.111504 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-12-03 11:29:54.111521 | controller |
2025-12-03 11:29:54.111528 | controller | Wednesday 03 December 2025  11:29:54 +0000 (0:00:00.042)       0:07:03.574 ****
2025-12-03 11:29:54.111534 | controller | ===============================================================================
2025-12-03 11:29:54.111540 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 283.54s
2025-12-03 11:29:54.111545 | controller | Wait for test node to be reachable via ssh ----------------------------- 26.71s
2025-12-03 11:29:54.111557 | controller | Wait a little to let the test instance boot. --------------------------- 20.05s
2025-12-03 11:29:54.111563 | controller | Download latest image -------------------------------------------------- 19.86s
2025-12-03 11:29:54.111572 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir --------------- 9.73s
2025-12-03 11:29:54.111744 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.28s
2025-12-03 11:29:54.111758 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.09s
2025-12-03 11:29:54.111764 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.53s
2025-12-03 11:29:54.111770 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.46s
2025-12-03 11:29:54.111775 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.56s
2025-12-03 11:29:54.111780 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.70s
2025-12-03 11:29:54.111786 | controller | discover_latest_image : Get latest image -------------------------------- 1.54s
2025-12-03 11:29:54.111791 | controller | config_drive : Install required RPM packages ---------------------------- 1.35s
2025-12-03 11:29:54.111800 | controller | config_drive : Install required RPM packages ---------------------------- 1.29s
2025-12-03 11:29:54.111946 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.09s
2025-12-03 11:29:54.112093 | controller | Grab some info from the test node --------------------------------------- 1.07s
2025-12-03 11:29:54.112229 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.04s
2025-12-03 11:29:54.112360 | controller | Grab some info from the nat64 appliance --------------------------------- 1.04s
2025-12-03 11:29:54.112591 | controller | Restart firewalld.service ----------------------------------------------- 0.96s
2025-12-03 11:29:54.112756 | controller | nat64_appliance : Restart firewalld.service ----------------------------- 0.85s
2025-12-03 11:29:54.177549 | controller | INFO     Running default > cleanup
2025-12-03 11:29:54.639758 | controller |
2025-12-03 11:29:54.639929 | controller | PLAY [Cleanup] *****************************************************************
2025-12-03 11:29:54.639974 | controller |
2025-12-03 11:29:54.640000 | controller | TASK [Gathering Facts] *********************************************************
2025-12-03 11:29:55.556064 | controller | Wednesday 03 December 2025  11:29:54 +0000 (0:00:00.054)       0:00:00.054 ****
2025-12-03 11:29:55.556114 | controller | ok: [instance]
2025-12-03 11:29:55.556140 | controller |
2025-12-03 11:29:55.556372 | controller | TASK [Destroy the test-node] ***************************************************
2025-12-03 11:29:56.116499 | controller | Wednesday 03 December 2025  11:29:55 +0000 (0:00:00.917)       0:00:00.971 ****
2025-12-03 11:29:56.116536 | controller | ok: [instance]
2025-12-03 11:29:56.337267 | controller |
2025-12-03 11:29:56.337298 | controller | TASK [Undefine the test-node] **************************************************
2025-12-03 11:29:56.337307 | controller | Wednesday 03 December 2025  11:29:56 +0000 (0:00:00.560)       0:00:01.531 ****
2025-12-03 11:29:56.337317 | controller | ok: [instance]
2025-12-03 11:29:56.705849 | controller |
2025-12-03 11:29:56.705879 | controller | TASK [Destroy the test network] ************************************************
2025-12-03 11:29:56.705887 | controller | Wednesday 03 December 2025  11:29:56 +0000 (0:00:00.220)       0:00:01.752 ****
2025-12-03 11:29:56.705897 | controller | ok: [instance]
2025-12-03 11:29:56.918440 | controller |
2025-12-03 11:29:56.918486 | controller | TASK [Undefine the test network] ***********************************************
2025-12-03 11:29:56.918495 | controller | Wednesday 03 December 2025  11:29:56 +0000 (0:00:00.368)       0:00:02.120 ****
2025-12-03 11:29:56.918505 | controller | ok: [instance]
2025-12-03 11:29:56.950347 | controller |
2025-12-03 11:29:56.950371 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-12-03 11:29:56.950380 | controller | Wednesday 03 December 2025  11:29:56 +0000 (0:00:00.212)       0:00:02.333 ****
2025-12-03 11:29:56.950397 | controller |
2025-12-03 11:29:57.238559 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-12-03 11:29:57.238590 | controller | Wednesday 03 December 2025  11:29:56 +0000 (0:00:00.032)       0:00:02.365 ****
2025-12-03 11:29:57.238602 | controller | changed: [instance]
2025-12-03 11:29:57.521144 | controller |
2025-12-03 11:29:57.521175 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-12-03 11:29:57.521184 | controller | Wednesday 03 December 2025  11:29:57 +0000 (0:00:00.287)       0:00:02.653 ****
2025-12-03 11:29:57.521199 | controller | ok: [instance]
2025-12-03 11:29:57.748073 | controller |
2025-12-03 11:29:57.748103 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-12-03 11:29:57.748112 | controller | Wednesday 03 December 2025  11:29:57 +0000 (0:00:00.282)       0:00:02.936 ****
2025-12-03 11:29:57.748122 | controller | ok: [instance]
2025-12-03 11:29:58.197311 | controller |
2025-12-03 11:29:58.197341 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-12-03 11:29:58.197350 | controller | Wednesday 03 December 2025  11:29:57 +0000 (0:00:00.226)       0:00:03.162 ****
2025-12-03 11:29:58.197360 | controller | ok: [instance]
2025-12-03 11:29:58.423666 | controller |
2025-12-03 11:29:58.423697 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-12-03 11:29:58.423706 | controller | Wednesday 03 December 2025  11:29:58 +0000 (0:00:00.449)       0:00:03.612 ****
2025-12-03 11:29:58.423716 | controller | ok: [instance]
2025-12-03 11:29:59.178712 | controller |
2025-12-03 11:29:59.178753 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-12-03 11:29:59.178762 | controller | Wednesday 03 December 2025  11:29:58 +0000 (0:00:00.226)       0:00:03.838 ****
2025-12-03 11:29:59.178773 | controller | ok: [instance] => (item=nat64-net-v4)
2025-12-03 11:29:59.179066 | controller | ok: [instance] => (item=nat64-net-v6)
2025-12-03 11:29:59.179081 | controller |
2025-12-03 11:29:59.643702 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-12-03 11:29:59.643734 | controller | Wednesday 03 December 2025  11:29:59 +0000 (0:00:00.755)       0:00:04.593 ****
2025-12-03 11:29:59.643747 | controller | ok: [instance] => (item=nat64-net-v4)
2025-12-03 11:29:59.643772 | controller | ok: [instance] => (item=nat64-net-v6)
2025-12-03 11:29:59.643778 | controller |
2025-12-03 11:29:59.643785 | controller | PLAY RECAP *********************************************************************
2025-12-03 11:29:59.643790 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-12-03 11:29:59.643796 | controller |
2025-12-03 11:29:59.643801 | controller | Wednesday 03 December 2025  11:29:59 +0000 (0:00:00.463)       0:00:05.057 ****
2025-12-03 11:29:59.643807 | controller | ===============================================================================
2025-12-03 11:29:59.643813 | controller | Gathering Facts --------------------------------------------------------- 0.92s
2025-12-03 11:29:59.643818 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.76s
2025-12-03 11:29:59.643823 | controller | Destroy the test-node --------------------------------------------------- 0.56s
2025-12-03 11:29:59.643829 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.46s
2025-12-03 11:29:59.643834 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.45s
2025-12-03 11:29:59.643839 | controller | Destroy the test network ------------------------------------------------ 0.37s
2025-12-03 11:29:59.643845 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.29s
2025-12-03 11:29:59.643850 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.28s
2025-12-03 11:29:59.643856 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.23s
2025-12-03 11:29:59.643861 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.23s
2025-12-03 11:29:59.643869 | controller | Undefine the test-node -------------------------------------------------- 0.22s
2025-12-03 11:29:59.643891 | controller | Undefine the test network ----------------------------------------------- 0.21s
2025-12-03 11:29:59.689931 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-12-03 11:29:59.689963 | controller | INFO     Writing /tmp/report.html report.
2025-12-03 11:30:00.183939 | [controller] Waiting on logger
2025-12-03 11:30:05.323421 | [controller] Waiting on logger
2025-12-03 11:30:15.755204 | [controller] Waiting on logger
2025-12-03 11:30:26.187401 | [controller] Waiting on logger
2025-12-03 11:30:29.768976 | [Zuul] Log Stream did not terminate
2025-12-03 11:30:29.769214 | controller | changed
2025-12-03 11:30:29.791963 | 
2025-12-03 11:30:29.792017 | PLAY RECAP
2025-12-03 11:30:29.792057 | controller | ok: 4 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-12-03 11:30:29.792079 | 
2025-12-03 11:30:29.863337 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-12-03 11:30:29.864236 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-12-03 11:30:30.388891 | 
2025-12-03 11:30:30.389001 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-12-03 11:30:30.409351 | 
2025-12-03 11:30:30.409429 | TASK [Filter out host if needed]
2025-12-03 11:30:30.417946 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-12-03 11:30:30.422357 | 
2025-12-03 11:30:30.422426 | TASK [Ensure file is present]
2025-12-03 11:30:30.735204 | controller | ok
2025-12-03 11:30:30.742003 | 
2025-12-03 11:30:30.742071 | TASK [Manage molecule report file]
2025-12-03 11:30:30.762435 | [controller] Waiting on logger
2025-12-03 11:30:41.163229 | [controller] Waiting on logger
2025-12-03 11:30:50.507254 | [controller] Waiting on logger
2025-12-03 11:31:00.939335 | [controller] Waiting on logger
2025-12-03 11:31:01.064374 | [Zuul] Log Stream did not terminate
2025-12-03 11:31:01.064486 | controller | changed
2025-12-03 11:31:01.069545 | 
2025-12-03 11:31:01.069610 | TASK [Check if we get ci-framework-data basedir]
2025-12-03 11:31:01.260658 | controller | ok
2025-12-03 11:31:01.265664 | 
2025-12-03 11:31:01.265745 | TASK [Create ci-framework-data log directory for zuul]
2025-12-03 11:31:01.557757 | controller | changed
2025-12-03 11:31:01.562763 | 
2025-12-03 11:31:01.562828 | TASK [Copy ci-framework interesting files]
2025-12-03 11:31:01.583604 | [controller] Waiting on logger
2025-12-03 11:31:12.011329 | [controller] Waiting on logger
2025-12-03 11:31:21.355336 | [controller] Waiting on logger
2025-12-03 11:31:31.773971 | [Zuul] Log Stream did not terminate
2025-12-03 11:31:31.774170 | controller | changed
2025-12-03 11:31:31.779441 | 
2025-12-03 11:31:31.779511 | TASK [Get SELinux listing]
2025-12-03 11:31:31.787294 | [controller] Waiting on logger
2025-12-03 11:31:32.811259 | [controller] Waiting on logger
2025-12-03 11:31:39.069250 | controller | changed
2025-12-03 11:31:39.074907 | 
2025-12-03 11:31:39.074996 | TASK [Generate log index]
2025-12-03 11:31:39.681738 | controller | changed
2025-12-03 11:31:39.686421 | 
2025-12-03 11:31:39.686488 | TASK [Get some env related data]
2025-12-03 11:31:40.747276 | [controller] Waiting on logger
2025-12-03 11:31:48.363360 | [controller] Waiting on logger
2025-12-03 11:31:51.416995 | controller | changed
2025-12-03 11:31:51.422239 | 
2025-12-03 11:31:51.422330 | TASK [Generate list of logs to collect in home directory]
2025-12-03 11:31:51.704465 | controller | ok: All paths examined
2025-12-03 11:31:51.709641 | 
2025-12-03 11:31:51.709745 | LOOP [Copy logs from home directory]
2025-12-03 11:31:52.009554 | controller | changed:
2025-12-03 11:31:52.009663 | controller | {
2025-12-03 11:31:52.009707 | controller |   "atime": 1764760776.3439229,
2025-12-03 11:31:52.009736 | controller |   "ctime": 1764760795.9538088,
2025-12-03 11:31:52.009754 | controller |   "dev": 64513,
2025-12-03 11:31:52.009770 | controller |   "gid": 1000,
2025-12-03 11:31:52.009785 | controller |   "gr_name": "zuul",
2025-12-03 11:31:52.009800 | controller |   "inode": 4336385,
2025-12-03 11:31:52.009814 | controller |   "isblk": false,
2025-12-03 11:31:52.009828 | controller |   "ischr": false,
2025-12-03 11:31:52.009842 | controller |   "isdir": false,
2025-12-03 11:31:52.009857 | controller |   "isfifo": false,
2025-12-03 11:31:52.009871 | controller |   "isgid": false,
2025-12-03 11:31:52.009885 | controller |   "islnk": false,
2025-12-03 11:31:52.009898 | controller |   "isreg": true,
2025-12-03 11:31:52.009912 | controller |   "issock": false,
2025-12-03 11:31:52.009925 | controller |   "isuid": false,
2025-12-03 11:31:52.009941 | controller |   "mode": "0644",
2025-12-03 11:31:52.009958 | controller |   "mtime": 1764760795.9538088,
2025-12-03 11:31:52.009973 | controller |   "nlink": 1,
2025-12-03 11:31:52.009987 | controller |   "path": "/home/zuul/ansible.log",
2025-12-03 11:31:52.010002 | controller |   "pw_name": "zuul",
2025-12-03 11:31:52.010017 | controller |   "rgrp": true,
2025-12-03 11:31:52.010032 | controller |   "roth": true,
2025-12-03 11:31:52.010046 | controller |   "rusr": true,
2025-12-03 11:31:52.010059 | controller |   "size": 6749,
2025-12-03 11:31:52.010074 | controller |   "uid": 1000,
2025-12-03 11:31:52.010088 | controller |   "wgrp": false,
2025-12-03 11:31:52.010101 | controller |   "woth": false,
2025-12-03 11:31:52.010115 | controller |   "wusr": true,
2025-12-03 11:31:52.010128 | controller |   "xgrp": false,
2025-12-03 11:31:52.010141 | controller |   "xoth": false,
2025-12-03 11:31:52.010154 | controller |   "xusr": false
2025-12-03 11:31:52.010168 | controller | }
2025-12-03 11:31:52.022749 | 
2025-12-03 11:31:52.022851 | TASK [Copy crio stats log file]
2025-12-03 11:31:52.036234 | controller | skipping: Conditional result was False
2025-12-03 11:31:52.041324 | 
2025-12-03 11:31:52.041394 | TASK [Get SELinux related data]
2025-12-03 11:31:57.066202 | controller | ERROR
2025-12-03 11:31:57.066441 | controller | {
2025-12-03 11:31:57.066479 | controller |   "delta": "0:00:00.008823",
2025-12-03 11:31:57.066504 | controller |   "end": "2025-12-03 11:31:52.241599",
2025-12-03 11:31:57.066526 | controller |   "msg": "non-zero return code",
2025-12-03 11:31:57.066546 | controller |   "rc": 1,
2025-12-03 11:31:57.066567 | controller |   "start": "2025-12-03 11:31:52.232776"
2025-12-03 11:31:57.066586 | controller | }
2025-12-03 11:31:57.066611 | controller | ERROR: Ignoring Errors
2025-12-03 11:31:57.071582 | 
2025-12-03 11:31:57.071647 | TASK [Create system configuration directory]
2025-12-03 11:31:57.254898 | controller | changed
2025-12-03 11:31:57.259737 | 
2025-12-03 11:31:57.259821 | TASK [Get some of the system configurations]
2025-12-03 11:31:57.280992 | [controller] Waiting on logger
2025-12-03 11:32:07.691358 | [controller] Waiting on logger
2025-12-03 11:32:18.123149 | [controller] Waiting on logger
2025-12-03 11:32:27.467421 | [controller] Waiting on logger
2025-12-03 11:32:27.492480 | [Zuul] Log Stream did not terminate
2025-12-03 11:32:27.493399 | controller | changed
2025-12-03 11:32:27.498452 | 
2025-12-03 11:32:27.498518 | TASK [Copy generated documentation if available]
2025-12-03 11:32:27.512489 | controller | skipping: Conditional result was False
2025-12-03 11:32:27.518342 | 
2025-12-03 11:32:27.518423 | TASK [Copy generated AsciiDoc documentation if available]
2025-12-03 11:32:27.534028 | controller | skipping: Conditional result was False
2025-12-03 11:32:27.540309 | 
2025-12-03 11:32:27.540377 | TASK [Compress logs bigger than 2MB]
2025-12-03 11:32:28.619259 | [controller] Waiting on logger
2025-12-03 11:32:34.877540 | controller | changed
2025-12-03 11:32:34.882887 | 
2025-12-03 11:32:34.882961 | TASK [Copy files from workspace on node]
2025-12-03 11:32:34.900425 | controller | ok
2025-12-03 11:32:34.921953 | 
2025-12-03 11:32:34.922020 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-03 11:32:34.934601 | controller | skipping: Conditional result was False
2025-12-03 11:32:34.939637 | 
2025-12-03 11:32:34.939724 | TASK [fetch-output : Set log path for single node]
2025-12-03 11:32:34.966812 | controller | ok
2025-12-03 11:32:34.972820 | 
2025-12-03 11:32:34.972891 | LOOP [fetch-output : Ensure local output dirs]
2025-12-03 11:32:35.156716 | controller -> localhost | ok: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/logs"
2025-12-03 11:32:35.156923 | controller -> localhost | changed: All items complete
2025-12-03 11:32:35.156953 | 
2025-12-03 11:32:35.325867 | controller -> localhost | changed: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/artifacts"
2025-12-03 11:32:35.495655 | controller -> localhost | changed: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/docs"
2025-12-03 11:32:35.508319 | 
2025-12-03 11:32:35.508396 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-03 11:32:36.054909 | controller | changed:
2025-12-03 11:32:36.055083 | controller | .d..t...... ./
2025-12-03 11:32:36.055114 | controller | >f+++++++++ README.html
2025-12-03 11:32:36.055135 | controller | >f+++++++++ ansible-execution.log
2025-12-03 11:32:36.055168 | controller | >f+++++++++ ansible.log
2025-12-03 11:32:36.055186 | controller | >f+++++++++ dmesg.log
2025-12-03 11:32:36.055204 | controller | >f+++++++++ installed-pkgs.log
2025-12-03 11:32:36.055221 | controller | >f+++++++++ python.log
2025-12-03 11:32:36.055240 | controller | >f+++++++++ registries.conf
2025-12-03 11:32:36.055258 | controller | >f+++++++++ report.html
2025-12-03 11:32:36.055276 | controller | >f+++++++++ selinux-denials.log
2025-12-03 11:32:36.055293 | controller | >f+++++++++ selinux-listing.log
2025-12-03 11:32:36.055324 | controller | cd+++++++++ ci-framework-data/
2025-12-03 11:32:36.055342 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-12-03 11:32:36.055360 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-12-03 11:32:36.055376 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-12-03 11:32:36.055393 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-12-03 11:32:36.055409 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-12-03 11:32:36.055425 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-12-03 11:32:36.055444 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/3f4d3581-1788-57e3-9c73-6677d21a3050/
2025-12-03 11:32:36.055460 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/3f4d3581-1788-57e3-9c73-6677d21a3050/meta-data
2025-12-03 11:32:36.055478 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/3f4d3581-1788-57e3-9c73-6677d21a3050/network-config
2025-12-03 11:32:36.055496 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/3f4d3581-1788-57e3-9c73-6677d21a3050/user-data
2025-12-03 11:32:36.055512 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/93ddc0b7-dda1-546a-88a3-17b9c61e6ce9/
2025-12-03 11:32:36.055528 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/93ddc0b7-dda1-546a-88a3-17b9c61e6ce9/meta-data
2025-12-03 11:32:36.055545 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/93ddc0b7-dda1-546a-88a3-17b9c61e6ce9/network-config
2025-12-03 11:32:36.055562 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/93ddc0b7-dda1-546a-88a3-17b9c61e6ce9/user-data
2025-12-03 11:32:36.055578 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-12-03 11:32:36.055594 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-12-03 11:32:36.055618 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-12-03 11:32:36.055637 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-12-03 11:32:36.055654 | controller | cd+++++++++ ci-framework-data/logs/
2025-12-03 11:32:36.055676 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-12-03 11:32:36.055708 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-12-03 11:32:36.055743 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-12-03 11:32:36.055763 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-12-03 11:32:36.055781 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-12-03 11:32:36.055798 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-12-03 11:32:36.055815 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-12-03 11:32:36.055831 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-12-03 11:32:36.055847 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-12-03 11:32:36.055865 | controller | cd+++++++++ registries.conf.d/
2025-12-03 11:32:36.055883 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-12-03 11:32:36.055901 | controller | cd+++++++++ system-config/
2025-12-03 11:32:36.055919 | controller | cd+++++++++ system-config/libvirt/
2025-12-03 11:32:36.055935 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-12-03 11:32:36.055952 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-12-03 11:32:36.055969 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-12-03 11:32:36.055984 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-12-03 11:32:36.056001 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-12-03 11:32:36.056017 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-12-03 11:32:36.056033 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-12-03 11:32:36.056049 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-12-03 11:32:36.056066 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-12-03 11:32:36.056081 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-12-03 11:32:36.056098 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-12-03 11:32:36.056119 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-12-03 11:32:36.056135 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-12-03 11:32:36.056150 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-12-03 11:32:36.056165 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-12-03 11:32:36.056181 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-12-03 11:32:36.408051 | controller | changed: .d..t...... ./
2025-12-03 11:32:36.757038 | controller | changed: .d..t...... ./
2025-12-03 11:32:36.770391 | 
2025-12-03 11:32:36.770564 | TASK [Return artifact to Zuul]
2025-12-03 11:32:36.799577 | controller | ok
2025-12-03 11:32:36.819069 | 
2025-12-03 11:32:36.819138 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-12-03 11:32:36.819249 | 
2025-12-03 11:32:36.819278 | PLAY RECAP
2025-12-03 11:32:36.819338 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-12-03 11:32:36.819363 | 
2025-12-03 11:32:36.905153 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-12-03 11:32:36.905933 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-03 11:32:37.404210 | 
2025-12-03 11:32:37.404313 | PLAY [all]
2025-12-03 11:32:37.422107 | 
2025-12-03 11:32:37.422178 | TASK [include_role : fetch-output]
2025-12-03 11:32:37.450449 | controller | ok
2025-12-03 11:32:37.466907 | 
2025-12-03 11:32:37.466986 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-03 11:32:37.510421 | controller | skipping: Conditional result was False
2025-12-03 11:32:37.515817 | 
2025-12-03 11:32:37.515884 | TASK [fetch-output : Set log path for single node]
2025-12-03 11:32:37.543512 | controller | ok
2025-12-03 11:32:37.548354 | 
2025-12-03 11:32:37.548422 | LOOP [fetch-output : Ensure local output dirs]
2025-12-03 11:32:37.859439 | controller -> localhost | ok: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/logs"
2025-12-03 11:32:38.035671 | controller -> localhost | ok: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/artifacts"
2025-12-03 11:32:38.212168 | controller -> localhost | ok: "/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/docs"
2025-12-03 11:32:38.225655 | 
2025-12-03 11:32:38.225773 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-03 11:32:38.722988 | controller | ok
2025-12-03 11:32:38.723210 | controller | ok: All items complete
2025-12-03 11:32:38.723240 | 
2025-12-03 11:32:39.077240 | controller | ok
2025-12-03 11:32:39.432889 | controller | ok
2025-12-03 11:32:39.446608 | 
2025-12-03 11:32:39.446723 | TASK [include_role : fetch-output-openshift]
2025-12-03 11:32:39.460425 | controller | skipping: Conditional result was False
2025-12-03 11:32:39.465976 | 
2025-12-03 11:32:39.466041 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-03 11:32:39.796418 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006335
2025-12-03 11:32:39.984836 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006110
2025-12-03 11:32:40.010648 | 
2025-12-03 11:32:40.010742 | PLAY [all]
2025-12-03 11:32:40.024553 | 
2025-12-03 11:32:40.024622 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-12-03 11:32:40.409378 | controller | changed
2025-12-03 11:32:40.430442 | 
2025-12-03 11:32:40.430493 | PLAY RECAP
2025-12-03 11:32:40.430537 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-12-03 11:32:40.430560 | 
2025-12-03 11:32:40.496446 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-03 11:32:40.497211 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-12-03 11:32:41.034767 | 
2025-12-03 11:32:41.034864 | PLAY [localhost]
2025-12-03 11:32:41.051811 | 
2025-12-03 11:32:41.051887 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-03 11:32:41.352871 | localhost | changed
2025-12-03 11:32:41.357344 | 
2025-12-03 11:32:41.357435 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-03 11:32:41.375207 | localhost | ok
2025-12-03 11:32:41.382858 | 
2025-12-03 11:32:41.382926 | TASK [add-fileserver : Create SSH private key tempfile]
2025-12-03 11:32:41.674035 | localhost | changed
2025-12-03 11:32:41.679587 | 
2025-12-03 11:32:41.679669 | TASK [add-fileserver : Create SSH private key from secret]
2025-12-03 11:32:42.212974 | localhost | changed
2025-12-03 11:32:42.217826 | 
2025-12-03 11:32:42.217899 | TASK [add-fileserver : Add fileserver ssh key]
2025-12-03 11:32:42.538392 | localhost | Identity added: /var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/tmp/ansible.l57vfrin (/var/lib/zuul/builds/87ee27cfd709496cb8700cb94fbe5297/work/tmp/ansible.l57vfrin)
2025-12-03 11:32:42.538534 | localhost | ok: Runtime: 0:00:00.005728
2025-12-03 11:32:42.542595 | 
2025-12-03 11:32:42.542662 | TASK [add-fileserver : Remove SSH private key from disk]
2025-12-03 11:32:42.752488 | localhost | ok: Runtime: 0:00:00.004322
2025-12-03 11:32:42.757061 | 
2025-12-03 11:32:42.757130 | TASK [add-fileserver : Add fileserver to inventory]
2025-12-03 11:32:42.804820 | localhost | changed
2025-12-03 11:32:42.809799 | 
2025-12-03 11:32:42.809861 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-12-03 11:32:43.121223 | localhost | changed
2025-12-03 11:32:43.140446 | 
2025-12-03 11:32:43.140519 | PLAY [localhost]
2025-12-03 11:32:43.152142 | 
2025-12-03 11:32:43.152204 | TASK [Generate bulk log download script]
2025-12-03 11:32:43.170570 | localhost | ok
2025-12-03 11:32:43.181940 | 
2025-12-03 11:32:43.182007 | TASK [local-log-download : Check API endpoint is defined]
2025-12-03 11:32:43.209095 | localhost | ok: All assertions passed
2025-12-03 11:32:43.213685 | 
2025-12-03 11:32:43.213764 | TASK [local-log-download : Create download script]
2025-12-03 11:32:43.561093 | localhost -> localhost | changed
2025-12-03 11:32:43.569502 | 
2025-12-03 11:32:43.569578 | TASK [Register quick-download link]
2025-12-03 11:32:43.587193 | localhost | ok
2025-12-03 11:32:43.621590 | 
2025-12-03 11:32:43.621673 | PLAY [logserver.rdoproject.org]
2025-12-03 11:32:43.630996 | 
2025-12-03 11:32:43.631053 | TASK [Set zuul-log-path fact]
2025-12-03 11:32:43.647132 | logserver.rdoproject.org | ok
2025-12-03 11:32:43.655576 | 
2025-12-03 11:32:43.655639 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-03 11:32:43.681547 | logserver.rdoproject.org | ok
2025-12-03 11:32:43.686567 | 
2025-12-03 11:32:43.686631 | TASK [upload-logs : Create log directories]
2025-12-03 11:32:45.354496 | logserver.rdoproject.org | changed
2025-12-03 11:32:45.357463 | 
2025-12-03 11:32:45.357527 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-12-03 11:32:45.574005 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004637
2025-12-03 11:32:45.578571 | 
2025-12-03 11:32:45.578634 | TASK [upload-logs : Upload logs to log server]
2025-12-03 11:32:47.237097 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-12-03 11:32:47.239901 | 
2025-12-03 11:32:47.239977 | LOOP [upload-logs : Compress console log and json output]
2025-12-03 11:32:47.277645 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-03 11:32:47.285545 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-03 11:32:47.297923 | 
2025-12-03 11:32:47.298025 | LOOP [upload-logs : Upload compressed console log and json output]
2025-12-03 11:32:47.332105 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-03 11:32:47.332336 | 
2025-12-03 11:32:47.335354 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-03 11:32:47.346623 | 
2025-12-03 11:32:47.346750 | LOOP [upload-logs : Upload console log and json output]