2025-10-03 10:09:33.467244 | Job console starting...
2025-10-03 10:09:33.703821 | Updating repositories
2025-10-03 10:09:34.388509 | Preparing job workspace
2025-10-03 10:09:41.338439 | Running Ansible setup...
2025-10-03 10:09:44.371059 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-03 10:09:44.927930 | 
2025-10-03 10:09:44.928039 | PLAY [localhost]
2025-10-03 10:09:44.936886 | 
2025-10-03 10:09:44.936988 | TASK [Gathering Facts]
2025-10-03 10:09:45.868392 | localhost | ok
2025-10-03 10:09:45.881746 | 
2025-10-03 10:09:45.881861 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-03 10:09:46.241121 | localhost -> localhost | changed
2025-10-03 10:09:46.246447 | 
2025-10-03 10:09:46.246535 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-03 10:09:47.010363 | localhost -> localhost | changed
2025-10-03 10:09:47.019087 | 
2025-10-03 10:09:47.019170 | TASK [Setup log path fact]
2025-10-03 10:09:47.036297 | localhost | ok
2025-10-03 10:09:47.052539 | 
2025-10-03 10:09:47.052650 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 10:09:47.079810 | localhost | ok
2025-10-03 10:09:47.087544 | 
2025-10-03 10:09:47.087623 | TASK [emit-job-header : Print job information]
2025-10-03 10:09:47.115384 | # Job Information
2025-10-03 10:09:47.115532 | Ansible Version: 2.15.12
2025-10-03 10:09:47.115563 | Job: cifmw-molecule-nat64_appliance
2025-10-03 10:09:47.115585 | Pipeline: github-check
2025-10-03 10:09:47.115605 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-10-03 10:09:47.115624 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362
2025-10-03 10:09:47.115644 | Log URL (when completed): https://logserver.rdoproject.org/044/rdoproject.org/0448881d65974fc096ecbac67381707a/
2025-10-03 10:09:47.115664 | Event ID: 79314020-a03f-11f0-87f2-6df8ed647fba
2025-10-03 10:09:47.120037 | 
2025-10-03 10:09:47.120106 | LOOP [emit-job-header : Print node information]
2025-10-03 10:09:47.213453 | localhost | ok:
2025-10-03 10:09:47.213669 | localhost | # Node Information
2025-10-03 10:09:47.213700 | localhost | Inventory Hostname: controller
2025-10-03 10:09:47.213725 | localhost | Hostname: np0005468622
2025-10-03 10:09:47.213746 | localhost | Username: zuul
2025-10-03 10:09:47.213784 | localhost | Distro: CentOS 9
2025-10-03 10:09:47.213803 | localhost | Provider: ibm-bm4-nodepool
2025-10-03 10:09:47.213821 | localhost | Region: regionOne
2025-10-03 10:09:47.213839 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-10-03 10:09:47.213855 | localhost | Product Name: OpenStack Compute
2025-10-03 10:09:47.213872 | localhost | Interface IP: 192.168.26.81
2025-10-03 10:09:47.235174 | 
2025-10-03 10:09:47.235319 | PLAY [all]
2025-10-03 10:09:47.244547 | 
2025-10-03 10:09:47.244621 | TASK [Gather network facts]
2025-10-03 10:09:47.613181 | controller | ok
2025-10-03 10:09:47.627809 | 
2025-10-03 10:09:47.627877 | TASK [include_role : start-zuul-console]
2025-10-03 10:09:47.652234 | controller | ok
2025-10-03 10:09:47.664512 | 
2025-10-03 10:09:47.664597 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-03 10:09:47.967830 | controller | ok
2025-10-03 10:09:47.976499 | 
2025-10-03 10:09:47.976570 | TASK [include_role : add-build-sshkey]
2025-10-03 10:09:47.995296 | controller | ok
2025-10-03 10:09:48.008997 | 
2025-10-03 10:09:48.009073 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-03 10:09:48.217122 | controller -> localhost | ok
2025-10-03 10:09:48.223484 | 
2025-10-03 10:09:48.223570 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-03 10:09:48.243197 | controller | ok
2025-10-03 10:09:48.255944 | controller | included: /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-03 10:09:48.261324 | 
2025-10-03 10:09:48.261386 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-03 10:09:48.919074 | controller -> localhost | Generating public/private rsa key pair.
2025-10-03 10:09:48.919279 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/0448881d65974fc096ecbac67381707a_id_rsa.
2025-10-03 10:09:48.919332 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/0448881d65974fc096ecbac67381707a_id_rsa.pub.
2025-10-03 10:09:48.919360 | controller -> localhost | The key fingerprint is:
2025-10-03 10:09:48.919382 | controller -> localhost | SHA256:mDcknu517Rxli2yD6QUDgd/37hykh5KePg8FbHn4UJw zuul-build-sshkey
2025-10-03 10:09:48.919403 | controller -> localhost | The key's randomart image is:
2025-10-03 10:09:48.919423 | controller -> localhost | +---[RSA 3072]----+
2025-10-03 10:09:48.919442 | controller -> localhost | |       ..  ...   |
2025-10-03 10:09:48.919460 | controller -> localhost | |      .  o +E    |
2025-10-03 10:09:48.919478 | controller -> localhost | |      ..o.B .    |
2025-10-03 10:09:48.919496 | controller -> localhost | |     . *.o.=.    |
2025-10-03 10:09:48.919513 | controller -> localhost | |      = S o.o.+  |
2025-10-03 10:09:48.919530 | controller -> localhost | |     . . . X B.. |
2025-10-03 10:09:48.919546 | controller -> localhost | |      . . B @.+  |
2025-10-03 10:09:48.919577 | controller -> localhost | |     . . +.O =.. |
2025-10-03 10:09:48.919597 | controller -> localhost | |      .  .=o+.o  |
2025-10-03 10:09:48.919615 | controller -> localhost | +----[SHA256]-----+
2025-10-03 10:09:48.919661 | controller -> localhost | ok: Runtime: 0:00:00.311075
2025-10-03 10:09:48.931975 | 
2025-10-03 10:09:48.932238 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-03 10:09:48.951273 | controller | ok
2025-10-03 10:09:48.961623 | controller | included: /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-03 10:09:48.970948 | 
2025-10-03 10:09:48.971023 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-03 10:09:49.005006 | controller | skipping: Conditional result was False
2025-10-03 10:09:49.011171 | 
2025-10-03 10:09:49.011253 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-03 10:09:49.395880 | controller | changed
2025-10-03 10:09:49.400847 | 
2025-10-03 10:09:49.400946 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-03 10:09:49.605661 | controller | ok
2025-10-03 10:09:49.610778 | 
2025-10-03 10:09:49.610854 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-03 10:09:50.231793 | controller | changed
2025-10-03 10:09:50.237307 | 
2025-10-03 10:09:50.237374 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-03 10:09:50.823573 | controller | changed
2025-10-03 10:09:50.829415 | 
2025-10-03 10:09:50.829500 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-03 10:09:50.842695 | controller | skipping: Conditional result was False
2025-10-03 10:09:50.848455 | 
2025-10-03 10:09:50.848532 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-03 10:09:51.167232 | controller -> localhost | changed
2025-10-03 10:09:51.176940 | 
2025-10-03 10:09:51.177023 | TASK [add-build-sshkey : Add back temp key]
2025-10-03 10:09:51.551487 | controller -> localhost | Identity added: /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/0448881d65974fc096ecbac67381707a_id_rsa (zuul-build-sshkey)
2025-10-03 10:09:51.551684 | controller -> localhost | ok: Runtime: 0:00:00.006970
2025-10-03 10:09:51.557866 | 
2025-10-03 10:09:51.557958 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-03 10:09:51.880177 | controller | ok
2025-10-03 10:09:51.885103 | 
2025-10-03 10:09:51.885181 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-03 10:09:51.908781 | controller | skipping: Conditional result was False
2025-10-03 10:09:51.925151 | 
2025-10-03 10:09:51.925222 | TASK [include_role : validate-host]
2025-10-03 10:09:51.944665 | controller | ok
2025-10-03 10:09:51.971457 | 
2025-10-03 10:09:51.971545 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-03 10:09:51.999378 | controller | ok
2025-10-03 10:09:52.004126 | 
2025-10-03 10:09:52.004194 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-03 10:09:52.235836 | controller -> localhost | ok
2025-10-03 10:09:52.241808 | 
2025-10-03 10:09:52.241895 | TASK [validate-host : Collect information about the host]
2025-10-03 10:09:52.858900 | controller | ok
2025-10-03 10:09:52.868538 | 
2025-10-03 10:09:52.868629 | TASK [validate-host : Sanitize hostname]
2025-10-03 10:09:52.963527 | controller | ok
2025-10-03 10:09:52.968557 | 
2025-10-03 10:09:52.968625 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-03 10:09:53.377811 | controller -> localhost | changed
2025-10-03 10:09:53.384101 | 
2025-10-03 10:09:53.384181 | TASK [validate-host : Collect information about zuul worker]
2025-10-03 10:09:53.736967 | controller | ok
2025-10-03 10:09:53.741748 | 
2025-10-03 10:09:53.741845 | TASK [validate-host : Write out all zuul information for each host]
2025-10-03 10:09:54.123636 | controller -> localhost | changed
2025-10-03 10:09:54.134716 | 
2025-10-03 10:09:54.134842 | TASK [include_role : prepare-workspace-openshift]
2025-10-03 10:09:54.148506 | controller | skipping: Conditional result was False
2025-10-03 10:09:54.154862 | 
2025-10-03 10:09:54.154968 | TASK [include_role : remove-zuul-sshkey]
2025-10-03 10:09:54.168475 | controller | skipping: Conditional result was False
2025-10-03 10:09:54.174151 | 
2025-10-03 10:09:54.174305 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-03 10:09:54.378295 | controller | ok: "logs"
2025-10-03 10:09:54.378505 | controller | ok: All items complete
2025-10-03 10:09:54.378541 | 
2025-10-03 10:09:54.576829 | controller | ok: "artifacts"
2025-10-03 10:09:54.756354 | controller | ok: "docs"
2025-10-03 10:09:54.762813 | 
2025-10-03 10:09:54.762883 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-03 10:09:54.988457 | controller | changed: "logs"
2025-10-03 10:09:55.176895 | controller | changed: "artifacts"
2025-10-03 10:09:55.356079 | controller | changed: "docs"
2025-10-03 10:09:55.386394 | 
2025-10-03 10:09:55.386486 | PLAY RECAP
2025-10-03 10:09:55.386532 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-03 10:09:55.386561 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-03 10:09:55.386580 | 
2025-10-03 10:09:55.533238 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-03 10:09:55.534006 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-03 10:09:56.137263 | 
2025-10-03 10:09:56.137382 | PLAY [all]
2025-10-03 10:09:56.158441 | 
2025-10-03 10:09:56.158548 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-03 10:09:56.228385 | controller | ok
2025-10-03 10:09:56.233688 | 
2025-10-03 10:09:56.233825 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-03 10:09:56.624356 | controller | changed
2025-10-03 10:09:56.630179 | 
2025-10-03 10:09:56.630493 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-03 10:09:57.471489 | controller | changed
2025-10-03 10:09:57.481079 | 
2025-10-03 10:09:57.481167 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-10-03 10:09:57.854365 | controller | changed:
2025-10-03 10:09:57.854542 | controller | {
2025-10-03 10:09:57.854575 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-10-03 10:09:57.854607 | controller | }
2025-10-03 10:09:58.065861 | controller | changed:
2025-10-03 10:09:58.065977 | controller | {
2025-10-03 10:09:58.066010 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-10-03 10:09:58.066034 | controller | }
2025-10-03 10:09:58.285878 | controller | changed:
2025-10-03 10:09:58.285992 | controller | {
2025-10-03 10:09:58.286022 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-10-03 10:09:58.286044 | controller | }
2025-10-03 10:09:58.505647 | controller | changed:
2025-10-03 10:09:58.505734 | controller | {
2025-10-03 10:09:58.505774 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-10-03 10:09:58.505797 | controller | }
2025-10-03 10:09:58.712382 | controller | changed:
2025-10-03 10:09:58.712492 | controller | {
2025-10-03 10:09:58.712521 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-10-03 10:09:58.712543 | controller | }
2025-10-03 10:09:58.927681 | controller | changed:
2025-10-03 10:09:58.927882 | controller | {
2025-10-03 10:09:58.928003 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-10-03 10:09:58.928030 | controller | }
2025-10-03 10:09:59.149629 | controller | changed:
2025-10-03 10:09:59.149721 | controller | {
2025-10-03 10:09:59.149761 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2025-10-03 10:09:59.149787 | controller | }
2025-10-03 10:09:59.362523 | controller | changed:
2025-10-03 10:09:59.362619 | controller | {
2025-10-03 10:09:59.362649 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2025-10-03 10:09:59.362671 | controller | }
2025-10-03 10:09:59.574328 | controller | changed:
2025-10-03 10:09:59.574436 | controller | {
2025-10-03 10:09:59.574465 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-10-03 10:09:59.574488 | controller | }
2025-10-03 10:09:59.788975 | controller | changed:
2025-10-03 10:09:59.789067 | controller | {
2025-10-03 10:09:59.789094 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-10-03 10:09:59.789115 | controller | }
2025-10-03 10:10:00.016924 | controller | changed:
2025-10-03 10:10:00.017007 | controller | {
2025-10-03 10:10:00.017036 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-10-03 10:10:00.017057 | controller | }
2025-10-03 10:10:00.234188 | controller | changed:
2025-10-03 10:10:00.234274 | controller | {
2025-10-03 10:10:00.234303 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-10-03 10:10:00.234324 | controller | }
2025-10-03 10:10:00.443353 | controller | changed:
2025-10-03 10:10:00.443442 | controller | {
2025-10-03 10:10:00.443470 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-10-03 10:10:00.443491 | controller | }
2025-10-03 10:10:00.663646 | controller | changed:
2025-10-03 10:10:00.663739 | controller | {
2025-10-03 10:10:00.663784 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-10-03 10:10:00.663806 | controller | }
2025-10-03 10:10:00.886695 | controller | changed:
2025-10-03 10:10:00.886798 | controller | {
2025-10-03 10:10:00.886828 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-10-03 10:10:00.886849 | controller | }
2025-10-03 10:10:01.103447 | controller | changed:
2025-10-03 10:10:01.103538 | controller | {
2025-10-03 10:10:01.103566 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-10-03 10:10:01.103587 | controller | }
2025-10-03 10:10:01.311497 | controller | changed:
2025-10-03 10:10:01.311581 | controller | {
2025-10-03 10:10:01.311609 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2025-10-03 10:10:01.311631 | controller | }
2025-10-03 10:10:01.518420 | controller | changed:
2025-10-03 10:10:01.518517 | controller | {
2025-10-03 10:10:01.518544 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2025-10-03 10:10:01.518575 | controller | }
2025-10-03 10:10:01.729811 | controller | changed:
2025-10-03 10:10:01.729891 | controller | {
2025-10-03 10:10:01.730131 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-10-03 10:10:01.730166 | controller | }
2025-10-03 10:10:01.939045 | controller | changed:
2025-10-03 10:10:01.939133 | controller | {
2025-10-03 10:10:01.939162 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-10-03 10:10:01.939184 | controller | }
2025-10-03 10:10:02.156028 | controller | changed:
2025-10-03 10:10:02.156106 | controller | {
2025-10-03 10:10:02.156134 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-10-03 10:10:02.156155 | controller | }
2025-10-03 10:10:02.365538 | controller | changed:
2025-10-03 10:10:02.365615 | controller | {
2025-10-03 10:10:02.365642 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-10-03 10:10:02.365662 | controller | }
2025-10-03 10:10:02.570661 | controller | changed:
2025-10-03 10:10:02.570758 | controller | {
2025-10-03 10:10:02.570786 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2025-10-03 10:10:02.570808 | controller | }
2025-10-03 10:10:02.779668 | controller | changed:
2025-10-03 10:10:02.779761 | controller | {
2025-10-03 10:10:02.779792 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-10-03 10:10:02.779815 | controller | }
2025-10-03 10:10:03.005490 | controller | changed:
2025-10-03 10:10:03.005658 | controller | {
2025-10-03 10:10:03.005696 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-10-03 10:10:03.005719 | controller | }
2025-10-03 10:10:03.220663 | controller | changed:
2025-10-03 10:10:03.220885 | controller | {
2025-10-03 10:10:03.220955 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-10-03 10:10:03.220981 | controller | }
2025-10-03 10:10:03.247393 | 
2025-10-03 10:10:03.247501 | TASK [Set timezone to UTC]
2025-10-03 10:10:03.650734 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-10-03 10:10:03.657413 | 
2025-10-03 10:10:03.657498 | TASK [Create nodepool directory]
2025-10-03 10:10:03.860656 | controller | changed
2025-10-03 10:10:03.866230 | 
2025-10-03 10:10:03.866298 | TASK [Create nodepool sub_nodes file]
2025-10-03 10:10:04.482298 | controller | changed
2025-10-03 10:10:04.487701 | 
2025-10-03 10:10:04.487779 | TASK [Create nodepool sub_nodes_private file]
2025-10-03 10:10:05.042077 | controller | changed
2025-10-03 10:10:05.047421 | 
2025-10-03 10:10:05.047485 | LOOP [Populate nodepool sub_nodes file]
2025-10-03 10:10:05.076743 | 
2025-10-03 10:10:05.076886 | LOOP [Populate nodepool sub_nodes_private file]
2025-10-03 10:10:05.115331 | 
2025-10-03 10:10:05.115474 | TASK [Create nodepool primary file]
2025-10-03 10:10:05.139376 | controller | skipping: Conditional result was False
2025-10-03 10:10:05.144886 | 
2025-10-03 10:10:05.145154 | TASK [Create nodepool node_private for this node]
2025-10-03 10:10:05.775293 | controller | changed
2025-10-03 10:10:05.780786 | 
2025-10-03 10:10:05.780869 | LOOP [Copy ssh keys to nodepool directory]
2025-10-03 10:10:06.170705 | controller | ok: Item: id_rsa Runtime: 0:00:00.007995
2025-10-03 10:10:06.170955 | 
2025-10-03 10:10:06.326546 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005951
2025-10-03 10:10:06.342143 | 
2025-10-03 10:10:06.342258 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-10-03 10:10:06.888575 | controller | changed
2025-10-03 10:10:06.894125 | 
2025-10-03 10:10:06.894247 | TASK [Validate sudoers config after edits]
2025-10-03 10:10:07.122650 | controller | /etc/sudoers: parsed OK
2025-10-03 10:10:07.122741 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-10-03 10:10:07.122753 | controller | /etc/sudoers.d/zuul: parsed OK
2025-10-03 10:10:07.122760 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-10-03 10:10:07.424312 | controller | ok: Runtime: 0:00:00.005457
2025-10-03 10:10:07.430205 | 
2025-10-03 10:10:07.430297 | TASK [Show the environment passed in to job shell scripts]
2025-10-03 10:10:07.681174 | controller | SHELL=/bin/bash
2025-10-03 10:10:07.681232 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-10-03 10:10:07.681242 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-10-03 10:10:07.681249 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/62/3362/41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-03 10:10:07.681256 | controller | PWD=/home/zuul
2025-10-03 10:10:07.681261 | controller | ZUUL_PIPELINE=github-check
2025-10-03 10:10:07.681267 | controller | LOGNAME=zuul
2025-10-03 10:10:07.681273 | controller | XDG_SESSION_TYPE=tty
2025-10-03 10:10:07.681332 | controller | _=/usr/bin/env
2025-10-03 10:10:07.681340 | controller | MOTD_SHOWN=pam
2025-10-03 10:10:07.681346 | controller | HOME=/home/zuul
2025-10-03 10:10:07.681351 | controller | LANG=en_US.UTF-8
2025-10-03 10:10:07.681368 | controller | SSH_CONNECTION=192.168.26.12 50850 192.168.26.81 22
2025-10-03 10:10:07.681374 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2025-10-03 10:10:07.681383 | controller | ZUUL_CHANGE_IDS=3362,41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-03 10:10:07.681389 | controller | WORKSPACE=/home/zuul/workspace
2025-10-03 10:10:07.681395 | controller | XDG_SESSION_CLASS=user
2025-10-03 10:10:07.681401 | controller | SELINUX_ROLE_REQUESTED=
2025-10-03 10:10:07.681406 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-10-03 10:10:07.681411 | controller | USER=zuul
2025-10-03 10:10:07.681417 | controller | ZUUL_VOTING=True
2025-10-03 10:10:07.681422 | controller | BUILD_TIMEOUT=1800000
2025-10-03 10:10:07.681427 | controller | SELINUX_USE_CURRENT_RANGE=
2025-10-03 10:10:07.681433 | controller | SHLVL=1
2025-10-03 10:10:07.681438 | controller | ZUUL_PATCHSET=41f2edaa0ac45cd85919f70775e84cf472326a6e
2025-10-03 10:10:07.681444 | controller | XDG_SESSION_ID=1
2025-10-03 10:10:07.681449 | controller | ZUUL_BRANCH=main
2025-10-03 10:10:07.681454 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-10-03 10:10:07.681460 | controller | SSH_CLIENT=192.168.26.12 50850 22
2025-10-03 10:10:07.681465 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-10-03 10:10:07.681470 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-10-03 10:10:07.681476 | controller | which_declare=declare -f
2025-10-03 10:10:07.681482 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-10-03 10:10:07.681488 | controller | SELINUX_LEVEL_REQUESTED=
2025-10-03 10:10:07.681493 | controller | ZUUL_CHANGE=3362
2025-10-03 10:10:07.681498 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-10-03 10:10:07.681503 | controller | ZUUL_UUID=0448881d65974fc096ecbac67381707a
2025-10-03 10:10:07.681509 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-10-03 10:10:07.681517 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-10-03 10:10:07.681522 | controller | }
2025-10-03 10:10:07.982922 | controller | ok: Runtime: 0:00:00.006848
2025-10-03 10:10:07.988270 | 
2025-10-03 10:10:07.988530 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-10-03 10:10:08.012826 | controller | skipping: Conditional result was False
2025-10-03 10:10:08.019644 | 
2025-10-03 10:10:08.019767 | TASK [Symlink /home/zuul-worker/workspace]
2025-10-03 10:10:08.545209 | controller | skipping: Conditional result was False
2025-10-03 10:10:08.552787 | 
2025-10-03 10:10:08.552879 | TASK [Ensure legacy workspace directory]
2025-10-03 10:10:08.748702 | controller | changed
2025-10-03 10:10:08.785503 | 
2025-10-03 10:10:08.785624 | PLAY RECAP
2025-10-03 10:10:08.785669 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-03 10:10:08.785693 | 
2025-10-03 10:10:08.888721 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-03 10:10:08.889761 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-03 10:10:09.526511 | 
2025-10-03 10:10:09.526618 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-10-03 10:10:09.561020 | 
2025-10-03 10:10:09.561112 | TASK [Create zuul-output directory]
2025-10-03 10:10:09.907068 | controller | changed
2025-10-03 10:10:09.912094 | 
2025-10-03 10:10:09.912175 | TASK [Slurp Zuul inventory test]
2025-10-03 10:10:10.240045 | controller -> localhost | ok
2025-10-03 10:10:10.246893 | 
2025-10-03 10:10:10.247006 | TASK [Save zuul inventory]
2025-10-03 10:10:11.066442 | controller | changed
2025-10-03 10:10:11.071709 | 
2025-10-03 10:10:11.071795 | TASK [Save zuul vars without the change_message]
2025-10-03 10:10:11.673085 | controller | changed
2025-10-03 10:10:11.697662 | 
2025-10-03 10:10:11.697763 | PLAY RECAP
2025-10-03 10:10:11.697810 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-03 10:10:11.697834 | 
2025-10-03 10:10:11.825104 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-03 10:10:11.825887 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-03 10:10:12.525503 | 
2025-10-03 10:10:12.525625 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-10-03 10:10:12.552935 | 
2025-10-03 10:10:12.553067 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-10-03 10:10:12.572123 | controller | ok
2025-10-03 10:10:12.590546 | 
2025-10-03 10:10:12.590643 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-03 10:10:12.624514 | controller | skipping: Conditional result was False
2025-10-03 10:10:12.630418 | 
2025-10-03 10:10:12.630491 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-03 10:10:12.985553 | controller | ok
2025-10-03 10:10:12.995016 | 
2025-10-03 10:10:12.995094 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-03 10:10:13.856377 | controller | ok
2025-10-03 10:10:13.875473 | 
2025-10-03 10:10:13.875565 | TASK [Prepare workspace]
2025-10-03 10:10:13.921223 | controller | ok
2025-10-03 10:10:13.986701 | 
2025-10-03 10:10:13.986831 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-03 10:10:14.341604 | controller | ok
2025-10-03 10:10:14.373822 | 
2025-10-03 10:10:14.373952 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-03 10:10:17.221392 | controller | Output suppressed because no_log was given
2025-10-03 10:10:17.239137 | 
2025-10-03 10:10:17.239239 | LOOP [Create zuul-output directory]
2025-10-03 10:10:17.491946 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-10-03 10:10:17.662278 | controller | ok: "/home/zuul/zuul-output/logs"
2025-10-03 10:10:17.672563 | 
2025-10-03 10:10:17.672664 | TASK [Install required packages]
2025-10-03 10:11:21.748025 | controller | changed
2025-10-03 10:11:21.754553 | 
2025-10-03 10:11:21.754630 | TASK [Install venv]
2025-10-03 10:12:31.827199 | controller | changed
2025-10-03 10:12:31.894525 | 
2025-10-03 10:12:31.894611 | PLAY RECAP
2025-10-03 10:12:31.894656 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-03 10:12:31.894680 | 
2025-10-03 10:12:32.002205 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-03 10:12:32.003126 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-03 10:12:32.575760 | 
2025-10-03 10:12:32.575868 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-10-03 10:12:32.596372 | 
2025-10-03 10:12:32.596462 | TASK [Gather required facts]
2025-10-03 10:12:33.092189 | controller | ok
2025-10-03 10:12:33.098367 | 
2025-10-03 10:12:33.098476 | TASK [Load environment var if instructed to]
2025-10-03 10:12:33.122792 | controller | skipping: Conditional result was False
2025-10-03 10:12:33.128618 | 
2025-10-03 10:12:33.128699 | TASK [Run molecule]
2025-10-03 10:12:34.076367 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-10-03 10:12:34.146442 | controller | INFO     Performing prerun with role_name_check=0...
2025-10-03 10:12:50.973779 | 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-10-03 10:12:50.974251 | 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-10-03 10:12:50.974721 | 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-10-03 10:12:50.975208 | 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-10-03 10:12:50.975695 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+41f2edaa was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+41f2edaa (/home/zuul/.ansible/collections/ansible_collections).
2025-10-03 10:12:50.976158 | 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-10-03 10:12:50.976615 | 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-10-03 10:12:50.977044 | 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-10-03 10:12:50.977491 | 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-10-03 10:12:50.977937 | 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-10-03 10:12:50.978416 | 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-10-03 10:12:50.978857 | 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-10-03 10:12:50.979312 | 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-10-03 10:12:50.979755 | 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-10-03 10:12:50.980238 | 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-10-03 10:12:50.989967 | controller | INFO     Running default > prepare
2025-10-03 10:12:51.686508 | controller |
2025-10-03 10:12:51.686603 | controller | PLAY [Prepare] *****************************************************************
2025-10-03 10:12:51.686697 | controller |
2025-10-03 10:12:51.686798 | controller | TASK [Gathering Facts] *********************************************************
2025-10-03 10:12:51.686900 | controller | Friday 03 October 2025  10:12:51 +0000 (0:00:00.020)       0:00:00.020 ********
2025-10-03 10:12:52.524913 | controller | ok: [instance]
2025-10-03 10:12:52.524989 | controller |
2025-10-03 10:12:52.525131 | controller | TASK [Create custom basedir] ***************************************************
2025-10-03 10:12:52.525247 | controller | Friday 03 October 2025  10:12:52 +0000 (0:00:00.838)       0:00:00.859 ********
2025-10-03 10:12:52.833432 | controller | ok: [instance]
2025-10-03 10:12:52.833481 | controller |
2025-10-03 10:12:52.833574 | controller | TASK [Install some debug utils] ************************************************
2025-10-03 10:12:52.833676 | controller | Friday 03 October 2025  10:12:52 +0000 (0:00:00.308)       0:00:01.168 ********
2025-10-03 10:12:56.294153 | controller | changed: [instance]
2025-10-03 10:12:56.294268 | controller |
2025-10-03 10:12:56.294389 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-10-03 10:12:56.294504 | controller | Friday 03 October 2025  10:12:56 +0000 (0:00:03.460)       0:00:04.629 ********
2025-10-03 10:12:56.310115 | controller | skipping: [instance]
2025-10-03 10:12:56.310234 | controller |
2025-10-03 10:12:56.310361 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-10-03 10:12:56.310480 | controller | Friday 03 October 2025  10:12:56 +0000 (0:00:00.016)       0:00:04.645 ********
2025-10-03 10:12:56.348466 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-10-03 10:12:56.348553 | controller |
2025-10-03 10:12:56.348665 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-10-03 10:12:56.348765 | controller | Friday 03 October 2025  10:12:56 +0000 (0:00:00.038)       0:00:04.683 ********
2025-10-03 10:12:56.622248 | controller | ok: [instance]
2025-10-03 10:12:56.622301 | controller |
2025-10-03 10:12:56.622426 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-10-03 10:12:56.622518 | controller | Friday 03 October 2025  10:12:56 +0000 (0:00:00.273)       0:00:04.957 ********
2025-10-03 10:12:56.836759 | controller | ok: [instance]
2025-10-03 10:12:56.836814 | controller |
2025-10-03 10:12:56.836939 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-10-03 10:12:56.837047 | controller | Friday 03 October 2025  10:12:56 +0000 (0:00:00.214)       0:00:05.171 ********
2025-10-03 10:12:57.530047 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-10-03 10:12:57.530589 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-10-03 10:12:57.590959 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-10-03 10:12:57.590994 | controller |
2025-10-03 10:12:57.591002 | controller | TASK [Deploy repo-setup] *******************************************************
2025-10-03 10:12:57.591008 | controller | Friday 03 October 2025  10:12:57 +0000 (0:00:00.693)       0:00:05.865 ********
2025-10-03 10:12:57.591018 | controller |
2025-10-03 10:12:58.134678 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-10-03 10:12:58.134710 | controller | Friday 03 October 2025  10:12:57 +0000 (0:00:00.060)       0:00:05.925 ********
2025-10-03 10:12:58.134722 | controller | changed: [instance] => (item=tmp)
2025-10-03 10:12:58.809167 | controller | changed: [instance] => (item=artifacts/repositories)
2025-10-03 10:12:58.809201 | controller | changed: [instance] => (item=venv/repo_setup)
2025-10-03 10:12:58.809216 | controller |
2025-10-03 10:12:58.809225 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-10-03 10:12:58.809233 | controller | Friday 03 October 2025  10:12:58 +0000 (0:00:00.543)       0:00:06.469 ********
2025-10-03 10:12:58.809243 | controller | ok: [instance]
2025-10-03 10:12:59.937896 | controller |
2025-10-03 10:12:59.937941 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-10-03 10:12:59.937950 | controller | Friday 03 October 2025  10:12:58 +0000 (0:00:00.674)       0:00:07.143 ********
2025-10-03 10:12:59.937960 | controller | changed: [instance]
2025-10-03 10:13:08.022189 | controller |
2025-10-03 10:13:08.022222 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-10-03 10:13:08.022230 | controller | Friday 03 October 2025  10:12:59 +0000 (0:00:01.128)       0:00:08.272 ********
2025-10-03 10:13:08.022240 | controller | changed: [instance]
2025-10-03 10:13:08.022263 | controller |
2025-10-03 10:13:08.022271 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-10-03 10:13:08.022291 | controller | Friday 03 October 2025  10:13:08 +0000 (0:00:08.084)       0:00:16.357 ********
2025-10-03 10:13:08.765660 | controller | changed: [instance]
2025-10-03 10:13:08.786662 | controller |
2025-10-03 10:13:08.786686 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-10-03 10:13:08.786696 | controller | Friday 03 October 2025  10:13:08 +0000 (0:00:00.743)       0:00:17.100 ********
2025-10-03 10:13:08.786707 | controller | skipping: [instance]
2025-10-03 10:13:09.625162 | controller |
2025-10-03 10:13:09.625193 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-10-03 10:13:09.625202 | controller | Friday 03 October 2025  10:13:08 +0000 (0:00:00.021)       0:00:17.121 ********
2025-10-03 10:13:09.625211 | controller | changed: [instance]
2025-10-03 10:13:09.625286 | controller |
2025-10-03 10:13:09.625296 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-10-03 10:13:09.625304 | controller | Friday 03 October 2025  10:13:09 +0000 (0:00:00.837)       0:00:17.959 ********
2025-10-03 10:13:09.663055 | controller | skipping: [instance]
2025-10-03 10:13:09.701043 | controller |
2025-10-03 10:13:09.701071 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-10-03 10:13:09.701211 | controller | Friday 03 October 2025  10:13:09 +0000 (0:00:00.038)       0:00:17.997 ********
2025-10-03 10:13:09.701236 | controller | skipping: [instance]
2025-10-03 10:13:09.739165 | controller |
2025-10-03 10:13:09.739198 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-10-03 10:13:09.739207 | controller | Friday 03 October 2025  10:13:09 +0000 (0:00:00.037)       0:00:18.035 ********
2025-10-03 10:13:09.739217 | controller | skipping: [instance]
2025-10-03 10:13:10.297128 | controller |
2025-10-03 10:13:10.297160 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-10-03 10:13:10.297168 | controller | Friday 03 October 2025  10:13:09 +0000 (0:00:00.038)       0:00:18.073 ********
2025-10-03 10:13:10.297177 | controller | changed: [instance]
2025-10-03 10:13:10.769174 | controller |
2025-10-03 10:13:10.769207 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-10-03 10:13:10.769216 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.557)       0:00:18.631 ********
2025-10-03 10:13:10.769231 | controller | changed: [instance]
2025-10-03 10:13:10.797479 | controller |
2025-10-03 10:13:10.797504 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-10-03 10:13:10.797512 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.472)       0:00:19.103 ********
2025-10-03 10:13:10.797521 | controller | skipping: [instance]
2025-10-03 10:13:10.825836 | controller |
2025-10-03 10:13:10.825883 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-10-03 10:13:10.825892 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.028)       0:00:19.132 ********
2025-10-03 10:13:10.825902 | controller | skipping: [instance]
2025-10-03 10:13:10.854132 | controller |
2025-10-03 10:13:10.854158 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-10-03 10:13:10.854165 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.028)       0:00:19.160 ********
2025-10-03 10:13:10.854175 | controller | skipping: [instance]
2025-10-03 10:13:10.892874 | controller |
2025-10-03 10:13:10.892902 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-10-03 10:13:10.892910 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.028)       0:00:19.188 ********
2025-10-03 10:13:10.892928 | controller | ok: [instance]
2025-10-03 10:13:10.922674 | controller |
2025-10-03 10:13:10.922695 | controller | TASK [repo_setup : Create download directory] **********************************
2025-10-03 10:13:10.922704 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.038)       0:00:19.227 ********
2025-10-03 10:13:10.922715 | controller | skipping: [instance]
2025-10-03 10:13:10.951632 | controller |
2025-10-03 10:13:10.951661 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-10-03 10:13:10.951671 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.029)       0:00:19.257 ********
2025-10-03 10:13:10.951682 | controller | skipping: [instance]
2025-10-03 10:13:10.981251 | controller |
2025-10-03 10:13:10.981300 | controller | TASK [Download the RPM] ********************************************************
2025-10-03 10:13:10.981310 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.028)       0:00:19.286 ********
2025-10-03 10:13:10.981324 | controller | skipping: [instance]
2025-10-03 10:13:10.981355 | controller |
2025-10-03 10:13:10.981366 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-10-03 10:13:10.981441 | controller | Friday 03 October 2025  10:13:10 +0000 (0:00:00.029)       0:00:19.316 ********
2025-10-03 10:13:11.011159 | controller | skipping: [instance]
2025-10-03 10:13:11.011460 | controller |
2025-10-03 10:13:11.040688 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-10-03 10:13:11.040707 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.030)       0:00:19.346 ********
2025-10-03 10:13:11.040718 | controller | skipping: [instance]
2025-10-03 10:13:11.072665 | controller |
2025-10-03 10:13:11.072684 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-10-03 10:13:11.072692 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.029)       0:00:19.375 ********
2025-10-03 10:13:11.072701 | controller | skipping: [instance]
2025-10-03 10:13:11.103149 | controller |
2025-10-03 10:13:11.103174 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-10-03 10:13:11.103183 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.031)       0:00:19.407 ********
2025-10-03 10:13:11.103194 | controller | skipping: [instance]
2025-10-03 10:13:11.300415 | controller |
2025-10-03 10:13:11.300445 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-10-03 10:13:11.300454 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.030)       0:00:19.437 ********
2025-10-03 10:13:11.300463 | controller | ok: [instance]
2025-10-03 10:13:11.528459 | controller |
2025-10-03 10:13:11.528490 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-10-03 10:13:11.528498 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.197)       0:00:19.634 ********
2025-10-03 10:13:11.528507 | controller | changed: [instance]
2025-10-03 10:13:11.770525 | controller |
2025-10-03 10:13:11.770556 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-10-03 10:13:11.770564 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.228)       0:00:19.863 ********
2025-10-03 10:13:11.770574 | controller | changed: [instance]
2025-10-03 10:13:11.791723 | controller |
2025-10-03 10:13:11.791751 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-10-03 10:13:11.791759 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.242)       0:00:20.105 ********
2025-10-03 10:13:11.791769 | controller | skipping: [instance]
2025-10-03 10:13:11.814187 | controller |
2025-10-03 10:13:11.814212 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-10-03 10:13:11.814220 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.021)       0:00:20.126 ********
2025-10-03 10:13:11.814230 | controller | skipping: [instance]
2025-10-03 10:13:11.837029 | controller |
2025-10-03 10:13:11.837057 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-10-03 10:13:11.837070 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.022)       0:00:20.149 ********
2025-10-03 10:13:11.837099 | controller | skipping: [instance]
2025-10-03 10:13:11.860151 | controller |
2025-10-03 10:13:11.860175 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-10-03 10:13:11.860191 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.022)       0:00:20.171 ********
2025-10-03 10:13:11.860207 | controller | skipping: [instance]
2025-10-03 10:13:11.860223 | controller |
2025-10-03 10:13:11.860234 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-10-03 10:13:11.860340 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.023)       0:00:20.195 ********
2025-10-03 10:13:11.885149 | controller | skipping: [instance]
2025-10-03 10:13:11.885586 | controller |
2025-10-03 10:13:11.909182 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-10-03 10:13:11.909218 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.025)       0:00:20.220 ********
2025-10-03 10:13:11.909230 | controller | skipping: [instance]
2025-10-03 10:13:11.927870 | controller |
2025-10-03 10:13:11.927905 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-10-03 10:13:11.927913 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.023)       0:00:20.244 ********
2025-10-03 10:13:11.927922 | controller | skipping: [instance]
2025-10-03 10:13:11.958272 | controller |
2025-10-03 10:13:11.958289 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-10-03 10:13:11.958296 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.018)       0:00:20.262 ********
2025-10-03 10:13:11.958305 | controller | skipping: [instance]
2025-10-03 10:13:11.976782 | controller |
2025-10-03 10:13:11.976799 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-10-03 10:13:11.976806 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.030)       0:00:20.293 ********
2025-10-03 10:13:11.976814 | controller | skipping: [instance]
2025-10-03 10:13:11.998672 | controller |
2025-10-03 10:13:11.998694 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-10-03 10:13:11.998702 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.018)       0:00:20.311 ********
2025-10-03 10:13:11.998713 | controller | skipping: [instance]
2025-10-03 10:13:11.998894 | controller |
2025-10-03 10:13:11.999068 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-10-03 10:13:11.999226 | controller | Friday 03 October 2025  10:13:11 +0000 (0:00:00.022)       0:00:20.334 ********
2025-10-03 10:13:12.028332 | controller | skipping: [instance]
2025-10-03 10:13:12.028505 | controller |
2025-10-03 10:13:12.028672 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-10-03 10:13:12.028837 | controller | Friday 03 October 2025  10:13:12 +0000 (0:00:00.029)       0:00:20.363 ********
2025-10-03 10:13:12.058016 | controller | skipping: [instance]
2025-10-03 10:13:12.086982 | controller |
2025-10-03 10:13:12.087002 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-10-03 10:13:12.087010 | controller | Friday 03 October 2025  10:13:12 +0000 (0:00:00.029)       0:00:20.393 ********
2025-10-03 10:13:12.087019 | controller | skipping: [instance]
2025-10-03 10:13:12.118680 | controller |
2025-10-03 10:13:12.118698 | controller | TASK [test_deps : Install additional packages] *********************************
2025-10-03 10:13:12.118705 | controller | Friday 03 October 2025  10:13:12 +0000 (0:00:00.029)       0:00:20.422 ********
2025-10-03 10:13:12.118713 | controller | skipping: [instance]
2025-10-03 10:14:03.403843 | controller |
2025-10-03 10:14:03.403875 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-10-03 10:14:03.403884 | controller | Friday 03 October 2025  10:13:12 +0000 (0:00:00.031)       0:00:20.453 ********
2025-10-03 10:14:03.403894 | controller | ok: [instance]
2025-10-03 10:14:04.554857 | controller |
2025-10-03 10:14:04.554887 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-10-03 10:14:04.554896 | controller | Friday 03 October 2025  10:14:03 +0000 (0:00:51.284)       0:01:11.738 ********
2025-10-03 10:14:04.554906 | controller | ok: [instance]
2025-10-03 10:14:04.587058 | controller |
2025-10-03 10:14:04.587102 | controller | TASK [test_deps : Install extra packages] **************************************
2025-10-03 10:14:04.587137 | controller | Friday 03 October 2025  10:14:04 +0000 (0:00:01.150)       0:01:12.889 ********
2025-10-03 10:14:04.587149 | controller | skipping: [instance]
2025-10-03 10:14:04.787859 | controller |
2025-10-03 10:14:04.787893 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-10-03 10:14:04.787901 | controller | Friday 03 October 2025  10:14:04 +0000 (0:00:00.032)       0:01:12.921 ********
2025-10-03 10:14:04.787911 | controller | ok: [instance]
2025-10-03 10:14:04.971826 | controller |
2025-10-03 10:14:04.971872 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-10-03 10:14:04.971880 | controller | Friday 03 October 2025  10:14:04 +0000 (0:00:00.200)       0:01:13.122 ********
2025-10-03 10:14:04.971895 | controller | changed: [instance]
2025-10-03 10:14:05.160888 | controller |
2025-10-03 10:14:05.160921 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-10-03 10:14:05.160929 | controller | Friday 03 October 2025  10:14:04 +0000 (0:00:00.184)       0:01:13.306 ********
2025-10-03 10:14:05.160939 | controller | ok: [instance]
2025-10-03 10:14:05.188775 | controller |
2025-10-03 10:14:05.188799 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-10-03 10:14:05.188806 | controller | Friday 03 October 2025  10:14:05 +0000 (0:00:00.188)       0:01:13.495 ********
2025-10-03 10:14:05.188816 | controller | skipping: [instance]
2025-10-03 10:14:05.205202 | controller |
2025-10-03 10:14:05.205235 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-10-03 10:14:05.205243 | controller | Friday 03 October 2025  10:14:05 +0000 (0:00:00.028)       0:01:13.523 ********
2025-10-03 10:14:05.205253 | controller | skipping: [instance]
2025-10-03 10:14:05.205293 | controller |
2025-10-03 10:14:05.205311 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-10-03 10:14:05.205321 | controller | Friday 03 October 2025  10:14:05 +0000 (0:00:00.016)       0:01:13.540 ********
2025-10-03 10:14:05.224958 | controller | ok: [instance]
2025-10-03 10:14:05.273194 | controller |
2025-10-03 10:14:05.273230 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-10-03 10:14:05.273240 | controller | Friday 03 October 2025  10:14:05 +0000 (0:00:00.019)       0:01:13.559 ********
2025-10-03 10:14:05.273252 | controller | skipping: [instance]
2025-10-03 10:15:25.686430 | controller |
2025-10-03 10:15:25.686463 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-10-03 10:15:25.686471 | controller | Friday 03 October 2025  10:14:05 +0000 (0:00:00.048)       0:01:13.608 ********
2025-10-03 10:15:25.686481 | controller | changed: [instance]
2025-10-03 10:15:25.686551 | controller |
2025-10-03 10:15:25.686562 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-10-03 10:15:25.686646 | controller | Friday 03 October 2025  10:15:25 +0000 (0:01:20.413)       0:02:34.021 ********
2025-10-03 10:15:25.887577 | controller | changed: [instance]
2025-10-03 10:15:26.268059 | controller |
2025-10-03 10:15:26.268111 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-10-03 10:15:26.268123 | controller | Friday 03 October 2025  10:15:25 +0000 (0:00:00.200)       0:02:34.222 ********
2025-10-03 10:15:26.268133 | controller | changed: [instance]
2025-10-03 10:15:26.851232 | controller |
2025-10-03 10:15:26.851263 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-10-03 10:15:26.851272 | controller | Friday 03 October 2025  10:15:26 +0000 (0:00:00.380)       0:02:34.602 ********
2025-10-03 10:15:26.851282 | controller | changed: [instance]
2025-10-03 10:15:27.049696 | controller |
2025-10-03 10:15:27.049727 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-10-03 10:15:27.049736 | controller | Friday 03 October 2025  10:15:26 +0000 (0:00:00.583)       0:02:35.185 ********
2025-10-03 10:15:27.049746 | controller | ok: [instance]
2025-10-03 10:15:27.049765 | controller |
2025-10-03 10:15:27.049945 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-10-03 10:15:27.741022 | controller | Friday 03 October 2025  10:15:27 +0000 (0:00:00.198)       0:02:35.384 ********
2025-10-03 10:15:27.741060 | controller | ok: [instance]
2025-10-03 10:15:28.594903 | controller |
2025-10-03 10:15:28.594939 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-10-03 10:15:28.594948 | controller | Friday 03 October 2025  10:15:27 +0000 (0:00:00.691)       0:02:36.075 ********
2025-10-03 10:15:28.594975 | controller | changed: [instance]
2025-10-03 10:15:28.595000 | controller |
2025-10-03 10:15:28.595151 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-10-03 10:15:28.595292 | controller | Friday 03 October 2025  10:15:28 +0000 (0:00:00.854)       0:02:36.929 ********
2025-10-03 10:15:28.670425 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-10-03 10:15:28.670469 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-10-03 10:15:28.671445 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-10-03 10:15:29.015225 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-10-03 10:15:29.015259 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-10-03 10:15:29.015267 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-10-03 10:15:29.015280 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-10-03 10:15:29.015286 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-10-03 10:15:29.015292 | controller |
2025-10-03 10:15:29.015298 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-10-03 10:15:29.015304 | controller | Friday 03 October 2025  10:15:28 +0000 (0:00:00.075)       0:02:37.005 ********
2025-10-03 10:15:29.015319 | controller | changed: [instance]
2025-10-03 10:15:29.015342 | controller |
2025-10-03 10:15:29.015413 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-10-03 10:15:29.015523 | controller | Friday 03 October 2025  10:15:29 +0000 (0:00:00.344)       0:02:37.350 ********
2025-10-03 10:15:29.365063 | controller | changed: [instance]
2025-10-03 10:15:29.716168 | controller |
2025-10-03 10:15:29.716200 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-10-03 10:15:29.716217 | controller | Friday 03 October 2025  10:15:29 +0000 (0:00:00.349)       0:02:37.699 ********
2025-10-03 10:15:29.716227 | controller | changed: [instance]
2025-10-03 10:15:30.058868 | controller |
2025-10-03 10:15:30.058897 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-10-03 10:15:30.058906 | controller | Friday 03 October 2025  10:15:29 +0000 (0:00:00.351)       0:02:38.050 ********
2025-10-03 10:15:30.058917 | controller | changed: [instance]
2025-10-03 10:15:30.059213 | controller |
2025-10-03 10:15:30.399750 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-10-03 10:15:30.399781 | controller | Friday 03 October 2025  10:15:30 +0000 (0:00:00.343)       0:02:38.394 ********
2025-10-03 10:15:30.399793 | controller | changed: [instance]
2025-10-03 10:15:30.746161 | controller |
2025-10-03 10:15:30.746192 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-10-03 10:15:30.746201 | controller | Friday 03 October 2025  10:15:30 +0000 (0:00:00.340)       0:02:38.734 ********
2025-10-03 10:15:30.746212 | controller | changed: [instance]
2025-10-03 10:15:30.746234 | controller |
2025-10-03 10:15:30.746242 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-10-03 10:15:30.746353 | controller | Friday 03 October 2025  10:15:30 +0000 (0:00:00.346)       0:02:39.081 ********
2025-10-03 10:15:31.080196 | controller | changed: [instance]
2025-10-03 10:15:31.080254 | controller |
2025-10-03 10:15:31.080436 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-10-03 10:15:31.413039 | controller | Friday 03 October 2025  10:15:31 +0000 (0:00:00.333)       0:02:39.415 ********
2025-10-03 10:15:31.413074 | controller | changed: [instance]
2025-10-03 10:15:31.753256 | controller |
2025-10-03 10:15:31.753295 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-10-03 10:15:31.753304 | controller | Friday 03 October 2025  10:15:31 +0000 (0:00:00.332)       0:02:39.747 ********
2025-10-03 10:15:31.753314 | controller | changed: [instance]
2025-10-03 10:15:31.753544 | controller |
2025-10-03 10:15:31.753559 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-10-03 10:15:32.099654 | controller | Friday 03 October 2025  10:15:31 +0000 (0:00:00.340)       0:02:40.088 ********
2025-10-03 10:15:32.099689 | controller | changed: [instance]
2025-10-03 10:15:32.458211 | controller |
2025-10-03 10:15:32.458244 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-10-03 10:15:32.458252 | controller | Friday 03 October 2025  10:15:32 +0000 (0:00:00.346)       0:02:40.434 ********
2025-10-03 10:15:32.458262 | controller | changed: [instance]
2025-10-03 10:15:32.797910 | controller |
2025-10-03 10:15:32.797946 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-10-03 10:15:32.797957 | controller | Friday 03 October 2025  10:15:32 +0000 (0:00:00.358)       0:02:40.792 ********
2025-10-03 10:15:32.797967 | controller | changed: [instance]
2025-10-03 10:15:33.141743 | controller |
2025-10-03 10:15:33.141773 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-10-03 10:15:33.141781 | controller | Friday 03 October 2025  10:15:32 +0000 (0:00:00.339)       0:02:41.132 ********
2025-10-03 10:15:33.141791 | controller | changed: [instance]
2025-10-03 10:15:33.504592 | controller |
2025-10-03 10:15:33.504625 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-10-03 10:15:33.504634 | controller | Friday 03 October 2025  10:15:33 +0000 (0:00:00.343)       0:02:41.476 ********
2025-10-03 10:15:33.504646 | controller | changed: [instance]
2025-10-03 10:15:33.863899 | controller |
2025-10-03 10:15:33.863929 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-10-03 10:15:33.863938 | controller | Friday 03 October 2025  10:15:33 +0000 (0:00:00.362)       0:02:41.839 ********
2025-10-03 10:15:33.863948 | controller | changed: [instance]
2025-10-03 10:15:34.193701 | controller |
2025-10-03 10:15:34.193731 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-10-03 10:15:34.193739 | controller | Friday 03 October 2025  10:15:33 +0000 (0:00:00.359)       0:02:42.198 ********
2025-10-03 10:15:34.193749 | controller | changed: [instance]
2025-10-03 10:15:34.524159 | controller |
2025-10-03 10:15:34.524189 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-10-03 10:15:34.524198 | controller | Friday 03 October 2025  10:15:34 +0000 (0:00:00.329)       0:02:42.528 ********
2025-10-03 10:15:34.524208 | controller | changed: [instance]
2025-10-03 10:15:34.854360 | controller |
2025-10-03 10:15:34.854392 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-10-03 10:15:34.854400 | controller | Friday 03 October 2025  10:15:34 +0000 (0:00:00.330)       0:02:42.859 ********
2025-10-03 10:15:34.854416 | controller | changed: [instance]
2025-10-03 10:15:35.199750 | controller |
2025-10-03 10:15:35.199781 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-10-03 10:15:35.199790 | controller | Friday 03 October 2025  10:15:34 +0000 (0:00:00.329)       0:02:43.189 ********
2025-10-03 10:15:35.199800 | controller | changed: [instance]
2025-10-03 10:15:35.545746 | controller |
2025-10-03 10:15:35.545776 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-10-03 10:15:35.545784 | controller | Friday 03 October 2025  10:15:35 +0000 (0:00:00.345)       0:02:43.534 ********
2025-10-03 10:15:35.545794 | controller | changed: [instance]
2025-10-03 10:15:35.881289 | controller |
2025-10-03 10:15:35.881319 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-10-03 10:15:35.881327 | controller | Friday 03 October 2025  10:15:35 +0000 (0:00:00.345)       0:02:43.880 ********
2025-10-03 10:15:35.881337 | controller | changed: [instance]
2025-10-03 10:15:36.221184 | controller |
2025-10-03 10:15:36.221219 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-10-03 10:15:36.221228 | controller | Friday 03 October 2025  10:15:35 +0000 (0:00:00.335)       0:02:44.216 ********
2025-10-03 10:15:36.221244 | controller | changed: [instance]
2025-10-03 10:15:36.563737 | controller |
2025-10-03 10:15:36.563765 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-10-03 10:15:36.563773 | controller | Friday 03 October 2025  10:15:36 +0000 (0:00:00.339)       0:02:44.556 ********
2025-10-03 10:15:36.563783 | controller | changed: [instance]
2025-10-03 10:15:36.902485 | controller |
2025-10-03 10:15:36.902514 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-10-03 10:15:36.902522 | controller | Friday 03 October 2025  10:15:36 +0000 (0:00:00.342)       0:02:44.898 ********
2025-10-03 10:15:36.902532 | controller | changed: [instance]
2025-10-03 10:15:36.921670 | controller |
2025-10-03 10:15:36.921699 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-10-03 10:15:36.921707 | controller | Friday 03 October 2025  10:15:36 +0000 (0:00:00.338)       0:02:45.237 ********
2025-10-03 10:15:36.921717 | controller | skipping: [instance]
2025-10-03 10:15:37.205168 | controller |
2025-10-03 10:15:37.205201 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-10-03 10:15:37.205210 | controller | Friday 03 October 2025  10:15:36 +0000 (0:00:00.019)       0:02:45.256 ********
2025-10-03 10:15:37.205220 | controller | ok: [instance]
2025-10-03 10:15:37.612841 | controller |
2025-10-03 10:15:37.612871 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-10-03 10:15:37.612879 | controller | Friday 03 October 2025  10:15:37 +0000 (0:00:00.283)       0:02:45.539 ********
2025-10-03 10:15:37.612889 | controller | changed: [instance]
2025-10-03 10:15:37.612920 | controller |
2025-10-03 10:15:37.613178 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-10-03 10:15:37.921256 | controller | Friday 03 October 2025  10:15:37 +0000 (0:00:00.407)       0:02:45.947 ********
2025-10-03 10:15:37.921290 | controller | changed: [instance]
2025-10-03 10:15:38.203462 | controller |
2025-10-03 10:15:38.203493 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-10-03 10:15:38.203501 | controller | Friday 03 October 2025  10:15:37 +0000 (0:00:00.307)       0:02:46.255 ********
2025-10-03 10:15:38.203511 | controller | [WARNING]: Reset is not implemented for this connection
2025-10-03 10:15:38.225248 | controller | changed: [instance]
2025-10-03 10:15:38.225307 | controller |
2025-10-03 10:15:38.225317 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-10-03 10:15:38.225325 | controller | Friday 03 October 2025  10:15:38 +0000 (0:00:00.277)       0:02:46.533 ********
2025-10-03 10:15:38.225332 | controller |
2025-10-03 10:15:38.225339 | controller | PLAY RECAP *********************************************************************
2025-10-03 10:15:38.225346 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-10-03 10:15:38.225355 | controller |
2025-10-03 10:15:38.225381 | controller | Friday 03 October 2025  10:15:38 +0000 (0:00:00.025)       0:02:46.559 ********
2025-10-03 10:15:38.227386 | controller | ===============================================================================
2025-10-03 10:15:38.287604 | controller | libvirt_manager : Install packages required for using KVM -------------- 80.41s
2025-10-03 10:15:38.287630 | controller | test_deps : Install selinux python libs -------------------------------- 51.28s
2025-10-03 10:15:38.287637 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.08s
2025-10-03 10:15:38.287643 | controller | Install some debug utils ------------------------------------------------ 3.46s
2025-10-03 10:15:38.287656 | controller | test_deps : Install python yaml libs ------------------------------------ 1.15s
2025-10-03 10:15:38.287662 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.13s
2025-10-03 10:15:38.287667 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.85s
2025-10-03 10:15:38.287672 | controller | Gathering Facts --------------------------------------------------------- 0.84s
2025-10-03 10:15:38.287678 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.84s
2025-10-03 10:15:38.287683 | controller | repo_setup : Install repo-setup package --------------------------------- 0.74s
2025-10-03 10:15:38.287688 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.69s
2025-10-03 10:15:38.287699 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.69s
2025-10-03 10:15:38.287704 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.67s
2025-10-03 10:15:38.287710 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.58s
2025-10-03 10:15:38.287715 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.56s
2025-10-03 10:15:38.287720 | controller | repo_setup : Ensure directories are present ----------------------------- 0.54s
2025-10-03 10:15:38.287726 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.47s
2025-10-03 10:15:38.287731 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.41s
2025-10-03 10:15:38.287736 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.38s
2025-10-03 10:15:38.287741 | controller | libvirt_manager : Ensure read-only socket is enabled for nwfilter. ------ 0.36s
2025-10-03 10:15:38.287751 | controller | INFO     Running default > converge
2025-10-03 10:15:38.728769 | controller |
2025-10-03 10:15:39.500584 | controller | PLAY [Converge] ****************************************************************
2025-10-03 10:15:39.500616 | controller |
2025-10-03 10:15:39.500624 | controller | TASK [Gathering Facts] *********************************************************
2025-10-03 10:15:39.500630 | controller | Friday 03 October 2025  10:15:38 +0000 (0:00:00.012)       0:00:00.012 ********
2025-10-03 10:15:39.500639 | controller | ok: [instance]
2025-10-03 10:15:39.861799 | controller |
2025-10-03 10:15:39.861844 | controller | TASK [Crate SSH keypair] *******************************************************
2025-10-03 10:15:39.861852 | controller | Friday 03 October 2025  10:15:39 +0000 (0:00:00.772)       0:00:00.785 ********
2025-10-03 10:15:39.861862 | controller | changed: [instance]
2025-10-03 10:15:40.357159 | controller |
2025-10-03 10:15:40.357190 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-10-03 10:15:40.357199 | controller | Friday 03 October 2025  10:15:39 +0000 (0:00:00.361)       0:00:01.146 ********
2025-10-03 10:15:40.357210 | controller | changed: [instance]
2025-10-03 10:15:40.357233 | controller |
2025-10-03 10:15:40.357480 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-03 10:15:41.307907 | controller | Friday 03 October 2025  10:15:40 +0000 (0:00:00.495)       0:00:01.641 ********
2025-10-03 10:15:41.307941 | controller | changed: [instance]
2025-10-03 10:15:41.344175 | controller |
2025-10-03 10:15:41.344205 | controller | TASK [Discover latest image] ***************************************************
2025-10-03 10:15:41.344214 | controller | Friday 03 October 2025  10:15:41 +0000 (0:00:00.950)       0:00:02.592 ********
2025-10-03 10:15:41.344224 | controller |
2025-10-03 10:15:41.344307 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-10-03 10:15:41.344319 | controller | Friday 03 October 2025  10:15:41 +0000 (0:00:00.036)       0:00:02.628 ********
2025-10-03 10:15:42.927080 | controller | changed: [instance]
2025-10-03 10:15:42.951535 | controller |
2025-10-03 10:15:42.951562 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-10-03 10:15:42.951576 | controller | Friday 03 October 2025  10:15:42 +0000 (0:00:01.582)       0:00:04.211 ********
2025-10-03 10:15:42.951586 | controller | ok: [instance]
2025-10-03 10:16:03.841986 | controller |
2025-10-03 10:16:03.842019 | controller | TASK [Download latest image] ***************************************************
2025-10-03 10:16:03.842028 | controller | Friday 03 October 2025  10:15:42 +0000 (0:00:00.024)       0:00:04.236 ********
2025-10-03 10:16:03.842039 | controller | changed: [instance]
2025-10-03 10:16:03.877604 | controller |
2025-10-03 10:16:03.877629 | controller | TASK [Build nat64 appliance image] *********************************************
2025-10-03 10:16:03.877637 | controller | Friday 03 October 2025  10:16:03 +0000 (0:00:20.890)       0:00:25.126 ********
2025-10-03 10:16:03.877646 | controller |
2025-10-03 10:16:04.363341 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-10-03 10:16:04.363373 | controller | Friday 03 October 2025  10:16:03 +0000 (0:00:00.035)       0:00:25.162 ********
2025-10-03 10:16:04.363392 | controller | ok: [instance] => (item=artifacts)
2025-10-03 10:16:04.561360 | controller | ok: [instance] => (item=logs)
2025-10-03 10:16:04.561390 | controller |
2025-10-03 10:16:04.561398 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-10-03 10:16:04.561404 | controller | Friday 03 October 2025  10:16:04 +0000 (0:00:00.485)       0:00:25.647 ********
2025-10-03 10:16:04.561413 | controller | changed: [instance]
2025-10-03 10:16:09.113527 | controller |
2025-10-03 10:16:09.113558 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-10-03 10:16:09.113566 | controller | Friday 03 October 2025  10:16:04 +0000 (0:00:00.198)       0:00:25.845 ********
2025-10-03 10:16:09.113576 | controller | ok: [instance]
2025-10-03 10:16:17.374185 | controller |
2025-10-03 10:16:17.374221 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-10-03 10:16:17.374229 | controller | Friday 03 October 2025  10:16:09 +0000 (0:00:04.552)       0:00:30.397 ********
2025-10-03 10:16:17.374240 | controller | changed: [instance]
2025-10-03 10:16:17.374263 | controller |
2025-10-03 10:16:17.374270 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-10-03 10:16:17.374277 | controller | Friday 03 October 2025  10:16:17 +0000 (0:00:08.260)       0:00:38.658 ********
2025-10-03 10:16:27.290105 | controller | changed: [instance] => (item=elements/)
2025-10-03 10:16:28.446674 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-10-03 10:16:28.446705 | controller |
2025-10-03 10:16:28.446713 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-10-03 10:16:28.446719 | controller | Friday 03 October 2025  10:16:27 +0000 (0:00:09.916)       0:00:48.574 ********
2025-10-03 10:16:28.446729 | controller | changed: [instance]
2025-10-03 10:20:48.314356 | controller |
2025-10-03 10:20:48.314473 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-10-03 10:20:48.314485 | controller | Friday 03 October 2025  10:16:28 +0000 (0:00:01.156)       0:00:49.731 ********
2025-10-03 10:20:48.314497 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-03 10:20:48.538015 | controller | changed: [instance]
2025-10-03 10:20:48.538053 | controller |
2025-10-03 10:20:48.538065 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-10-03 10:20:48.538073 | controller | Friday 03 October 2025  10:20:48 +0000 (0:04:19.867)       0:05:09.598 ********
2025-10-03 10:20:48.538099 | controller | changed: [instance]
2025-10-03 10:20:56.014628 | controller |
2025-10-03 10:20:56.014665 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-10-03 10:20:56.014673 | controller | Friday 03 October 2025  10:20:48 +0000 (0:00:00.223)       0:05:09.821 ********
2025-10-03 10:20:56.014684 | controller | changed: [instance]
2025-10-03 10:20:56.064593 | controller |
2025-10-03 10:20:56.064640 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-10-03 10:20:56.064649 | controller | Friday 03 October 2025  10:20:56 +0000 (0:00:07.477)       0:05:17.299 ********
2025-10-03 10:20:56.064662 | controller |
2025-10-03 10:20:56.124224 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-10-03 10:20:56.124269 | controller | Friday 03 October 2025  10:20:56 +0000 (0:00:00.050)       0:05:17.349 ********
2025-10-03 10:20:56.124284 | controller | ok: [instance]
2025-10-03 10:20:57.008199 | controller |
2025-10-03 10:20:57.008235 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-10-03 10:20:57.008244 | controller | Friday 03 October 2025  10:20:56 +0000 (0:00:00.059)       0:05:17.408 ********
2025-10-03 10:20:57.008261 | controller | changed: [instance]
2025-10-03 10:20:57.008359 | controller |
2025-10-03 10:20:57.008393 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-10-03 10:20:57.008406 | controller | Friday 03 October 2025  10:20:57 +0000 (0:00:00.883)       0:05:18.292 ********
2025-10-03 10:20:57.354184 | controller | ok: [instance]
2025-10-03 10:20:57.354419 | controller |
2025-10-03 10:20:57.354461 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-10-03 10:20:57.607452 | controller | Friday 03 October 2025  10:20:57 +0000 (0:00:00.346)       0:05:18.638 ********
2025-10-03 10:20:57.607500 | controller | ok: [instance]
2025-10-03 10:20:57.844190 | controller |
2025-10-03 10:20:57.844230 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-10-03 10:20:57.844239 | controller | Friday 03 October 2025  10:20:57 +0000 (0:00:00.253)       0:05:18.891 ********
2025-10-03 10:20:57.844252 | controller | changed: [instance]
2025-10-03 10:20:57.844278 | controller |
2025-10-03 10:20:57.844286 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-10-03 10:20:57.844386 | controller | Friday 03 October 2025  10:20:57 +0000 (0:00:00.236)       0:05:19.128 ********
2025-10-03 10:20:58.087240 | controller | changed: [instance]
2025-10-03 10:20:58.087462 | controller |
2025-10-03 10:20:58.087477 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-10-03 10:20:58.336899 | controller | Friday 03 October 2025  10:20:58 +0000 (0:00:00.243)       0:05:19.371 ********
2025-10-03 10:20:58.336939 | controller | ok: [instance]
2025-10-03 10:20:58.565896 | controller |
2025-10-03 10:20:58.565932 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-10-03 10:20:58.565940 | controller | Friday 03 October 2025  10:20:58 +0000 (0:00:00.249)       0:05:19.621 ********
2025-10-03 10:20:58.565952 | controller | ok: [instance]
2025-10-03 10:20:58.797450 | controller |
2025-10-03 10:20:58.797486 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-10-03 10:20:58.797494 | controller | Friday 03 October 2025  10:20:58 +0000 (0:00:00.229)       0:05:19.850 ********
2025-10-03 10:20:58.797506 | controller | changed: [instance]
2025-10-03 10:20:59.589015 | controller |
2025-10-03 10:20:59.589050 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-10-03 10:20:59.589058 | controller | Friday 03 October 2025  10:20:58 +0000 (0:00:00.231)       0:05:20.081 ********
2025-10-03 10:20:59.589069 | controller | changed: [instance] => (item=br-64v6)
2025-10-03 10:21:00.542163 | controller | changed: [instance] => (item=br-64v4)
2025-10-03 10:21:00.542198 | controller |
2025-10-03 10:21:00.542206 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-10-03 10:21:00.542213 | controller | Friday 03 October 2025  10:20:59 +0000 (0:00:00.791)       0:05:20.873 ********
2025-10-03 10:21:00.542223 | controller | changed: [instance]
2025-10-03 10:21:00.542295 | controller |
2025-10-03 10:21:00.542328 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-10-03 10:21:00.542341 | controller | Friday 03 October 2025  10:21:00 +0000 (0:00:00.953)       0:05:21.826 ********
2025-10-03 10:21:00.574239 | controller | ok: [instance]
2025-10-03 10:21:00.610762 | controller |
2025-10-03 10:21:00.610798 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-10-03 10:21:00.610806 | controller | Friday 03 October 2025  10:21:00 +0000 (0:00:00.032)       0:05:21.858 ********
2025-10-03 10:21:00.610816 | controller |
2025-10-03 10:21:01.026160 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-03 10:21:01.026194 | controller | Friday 03 October 2025  10:21:00 +0000 (0:00:00.036)       0:05:21.895 ********
2025-10-03 10:21:01.026206 | controller | ok: [instance] => (item=artifacts)
2025-10-03 10:21:02.379982 | controller | ok: [instance] => (item=logs)
2025-10-03 10:21:02.380015 | controller |
2025-10-03 10:21:02.380023 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-03 10:21:02.380029 | controller | Friday 03 October 2025  10:21:01 +0000 (0:00:00.414)       0:05:22.310 ********
2025-10-03 10:21:02.380039 | controller | ok: [instance]
2025-10-03 10:21:02.596795 | controller |
2025-10-03 10:21:02.596828 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-03 10:21:02.596837 | controller | Friday 03 October 2025  10:21:02 +0000 (0:00:01.354)       0:05:23.664 ********
2025-10-03 10:21:02.596847 | controller | changed: [instance]
2025-10-03 10:21:02.970941 | controller |
2025-10-03 10:21:02.970973 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-03 10:21:02.970981 | controller | Friday 03 October 2025  10:21:02 +0000 (0:00:00.216)       0:05:23.881 ********
2025-10-03 10:21:02.970991 | controller | changed: [instance]
2025-10-03 10:21:03.392028 | controller |
2025-10-03 10:21:03.392064 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-03 10:21:03.392073 | controller | Friday 03 October 2025  10:21:02 +0000 (0:00:00.374)       0:05:24.255 ********
2025-10-03 10:21:03.392103 | controller | changed: [instance]
2025-10-03 10:21:03.794192 | controller |
2025-10-03 10:21:03.794233 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-03 10:21:03.794249 | controller | Friday 03 October 2025  10:21:03 +0000 (0:00:00.420)       0:05:24.676 ********
2025-10-03 10:21:03.794260 | controller | changed: [instance]
2025-10-03 10:21:04.004654 | controller |
2025-10-03 10:21:04.004690 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-03 10:21:04.004698 | controller | Friday 03 October 2025  10:21:03 +0000 (0:00:00.401)       0:05:25.078 ********
2025-10-03 10:21:04.004708 | controller | ok: [instance]
2025-10-03 10:21:04.025641 | controller |
2025-10-03 10:21:04.025674 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-03 10:21:04.025683 | controller | Friday 03 October 2025  10:21:04 +0000 (0:00:00.210)       0:05:25.288 ********
2025-10-03 10:21:04.025695 | controller | skipping: [instance]
2025-10-03 10:21:04.270121 | controller |
2025-10-03 10:21:04.270158 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-03 10:21:04.270166 | controller | Friday 03 October 2025  10:21:04 +0000 (0:00:00.021)       0:05:25.310 ********
2025-10-03 10:21:04.270177 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-03 10:21:05.455328 | controller | changed: [instance]
2025-10-03 10:21:05.455358 | controller |
2025-10-03 10:21:05.455367 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-10-03 10:21:05.455373 | controller | Friday 03 October 2025  10:21:04 +0000 (0:00:00.244)       0:05:25.554 ********
2025-10-03 10:21:05.455383 | controller | changed: [instance]
2025-10-03 10:21:06.382322 | controller |
2025-10-03 10:21:06.382356 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-10-03 10:21:06.382365 | controller | Friday 03 October 2025  10:21:05 +0000 (0:00:01.185)       0:05:26.739 ********
2025-10-03 10:21:06.382375 | controller | changed: [instance]
2025-10-03 10:21:06.405910 | controller |
2025-10-03 10:21:06.405940 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-10-03 10:21:06.405948 | controller | Friday 03 October 2025  10:21:06 +0000 (0:00:00.924)       0:05:27.664 ********
2025-10-03 10:21:06.405959 | controller | ok: [instance]
2025-10-03 10:21:06.446730 | controller |
2025-10-03 10:21:06.446768 | controller | TASK [Set MAC address facts] ***************************************************
2025-10-03 10:21:06.446776 | controller | Friday 03 October 2025  10:21:06 +0000 (0:00:00.026)       0:05:27.690 ********
2025-10-03 10:21:06.446787 | controller | ok: [instance]
2025-10-03 10:21:06.690780 | controller |
2025-10-03 10:21:06.690819 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-10-03 10:21:06.690829 | controller | Friday 03 October 2025  10:21:06 +0000 (0:00:00.040)       0:05:27.731 ********
2025-10-03 10:21:06.690841 | controller | changed: [instance]
2025-10-03 10:21:06.975000 | controller |
2025-10-03 10:21:06.975034 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-10-03 10:21:06.975042 | controller | Friday 03 October 2025  10:21:06 +0000 (0:00:00.243)       0:05:27.974 ********
2025-10-03 10:21:06.975053 | controller | ok: [instance]
2025-10-03 10:21:07.225368 | controller |
2025-10-03 10:21:07.225403 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-10-03 10:21:07.225411 | controller | Friday 03 October 2025  10:21:06 +0000 (0:00:00.281)       0:05:28.256 ********
2025-10-03 10:21:07.225422 | controller | ok: [instance]
2025-10-03 10:21:07.451014 | controller |
2025-10-03 10:21:07.451051 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-10-03 10:21:07.451061 | controller | Friday 03 October 2025  10:21:07 +0000 (0:00:00.253)       0:05:28.509 ********
2025-10-03 10:21:07.451073 | controller | changed: [instance]
2025-10-03 10:21:07.793164 | controller |
2025-10-03 10:21:07.793198 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-10-03 10:21:07.793215 | controller | Friday 03 October 2025  10:21:07 +0000 (0:00:00.225)       0:05:28.735 ********
2025-10-03 10:21:07.793225 | controller | changed: [instance]
2025-10-03 10:21:07.793420 | controller |
2025-10-03 10:21:07.793435 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-03 10:21:08.634164 | controller | Friday 03 October 2025  10:21:07 +0000 (0:00:00.342)       0:05:29.077 ********
2025-10-03 10:21:08.634202 | controller | changed: [instance]
2025-10-03 10:21:08.670799 | controller |
2025-10-03 10:21:08.670831 | controller | TASK [Generate test node UUID] *************************************************
2025-10-03 10:21:08.670839 | controller | Friday 03 October 2025  10:21:08 +0000 (0:00:00.837)       0:05:29.914 ********
2025-10-03 10:21:08.670850 | controller | ok: [instance]
2025-10-03 10:21:16.726235 | controller |
2025-10-03 10:21:16.726287 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-10-03 10:21:16.726318 | controller | Friday 03 October 2025  10:21:08 +0000 (0:00:00.036)       0:05:29.951 ********
2025-10-03 10:21:16.726335 | controller | changed: [instance]
2025-10-03 10:21:16.726725 | controller |
2025-10-03 10:21:16.727100 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-10-03 10:21:16.727447 | controller | Friday 03 October 2025  10:21:16 +0000 (0:00:08.055)       0:05:38.007 ********
2025-10-03 10:21:16.772352 | controller |
2025-10-03 10:21:17.228889 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-03 10:21:17.228920 | controller | Friday 03 October 2025  10:21:16 +0000 (0:00:00.049)       0:05:38.057 ********
2025-10-03 10:21:17.228931 | controller | ok: [instance] => (item=artifacts)
2025-10-03 10:21:18.510809 | controller | ok: [instance] => (item=logs)
2025-10-03 10:21:18.510839 | controller |
2025-10-03 10:21:18.510847 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-03 10:21:18.510854 | controller | Friday 03 October 2025  10:21:17 +0000 (0:00:00.456)       0:05:38.513 ********
2025-10-03 10:21:18.510863 | controller | ok: [instance]
2025-10-03 10:21:18.718520 | controller |
2025-10-03 10:21:18.718549 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-03 10:21:18.718558 | controller | Friday 03 October 2025  10:21:18 +0000 (0:00:01.278)       0:05:39.792 ********
2025-10-03 10:21:18.718568 | controller | changed: [instance]
2025-10-03 10:21:19.081528 | controller |
2025-10-03 10:21:19.081560 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-03 10:21:19.081568 | controller | Friday 03 October 2025  10:21:18 +0000 (0:00:00.210)       0:05:40.003 ********
2025-10-03 10:21:19.081578 | controller | changed: [instance]
2025-10-03 10:21:19.459160 | controller |
2025-10-03 10:21:19.459194 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-03 10:21:19.459203 | controller | Friday 03 October 2025  10:21:19 +0000 (0:00:00.362)       0:05:40.365 ********
2025-10-03 10:21:19.459213 | controller | changed: [instance]
2025-10-03 10:21:19.459338 | controller |
2025-10-03 10:21:19.459350 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-03 10:21:19.459358 | controller | Friday 03 October 2025  10:21:19 +0000 (0:00:00.377)       0:05:40.743 ********
2025-10-03 10:21:19.840255 | controller | changed: [instance]
2025-10-03 10:21:19.840324 | controller |
2025-10-03 10:21:19.840334 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-03 10:21:19.840342 | controller | Friday 03 October 2025  10:21:19 +0000 (0:00:00.381)       0:05:41.125 ********
2025-10-03 10:21:20.026824 | controller | ok: [instance]
2025-10-03 10:21:20.026892 | controller |
2025-10-03 10:21:20.027006 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-03 10:21:20.027123 | controller | Friday 03 October 2025  10:21:20 +0000 (0:00:00.186)       0:05:41.311 ********
2025-10-03 10:21:20.047856 | controller | skipping: [instance]
2025-10-03 10:21:20.048200 | controller |
2025-10-03 10:21:20.263393 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-03 10:21:20.263423 | controller | Friday 03 October 2025  10:21:20 +0000 (0:00:00.018)       0:05:41.330 ********
2025-10-03 10:21:20.263435 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-03 10:21:20.536965 | controller | changed: [instance]
2025-10-03 10:21:20.536994 | controller |
2025-10-03 10:21:20.537002 | controller | TASK [Define test-node VM] *****************************************************
2025-10-03 10:21:20.537008 | controller | Friday 03 October 2025  10:21:20 +0000 (0:00:00.217)       0:05:41.547 ********
2025-10-03 10:21:20.537018 | controller | changed: [instance]
2025-10-03 10:21:21.385881 | controller |
2025-10-03 10:21:21.385916 | controller | TASK [Start test-node VM] ******************************************************
2025-10-03 10:21:21.385924 | controller | Friday 03 October 2025  10:21:20 +0000 (0:00:00.272)       0:05:41.820 ********
2025-10-03 10:21:21.385934 | controller | changed: [instance]
2025-10-03 10:21:50.124438 | controller |
2025-10-03 10:21:50.124483 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-10-03 10:21:50.124492 | controller | Friday 03 October 2025  10:21:21 +0000 (0:00:00.849)       0:05:42.670 ********
2025-10-03 10:21:50.124502 | controller | ok: [instance]
2025-10-03 10:21:50.144814 | controller |
2025-10-03 10:21:50.144847 | controller | TASK [Add test node to inventory] **********************************************
2025-10-03 10:21:50.144856 | controller | Friday 03 October 2025  10:21:50 +0000 (0:00:28.738)       0:06:11.408 ********
2025-10-03 10:21:50.144868 | controller | changed: [instance]
2025-10-03 10:21:50.163902 | controller |
2025-10-03 10:21:50.163931 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-10-03 10:21:50.163939 | controller | Friday 03 October 2025  10:21:50 +0000 (0:00:00.020)       0:06:11.429 ********
2025-10-03 10:21:50.163949 | controller | changed: [instance]
2025-10-03 10:22:10.203196 | controller |
2025-10-03 10:22:10.203230 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-10-03 10:22:10.203253 | controller | Friday 03 October 2025  10:21:50 +0000 (0:00:00.019)       0:06:11.448 ********
2025-10-03 10:22:10.203264 | controller | Pausing for 20 seconds
2025-10-03 10:22:16.754614 | controller | ok: [instance]
2025-10-03 10:22:16.754647 | controller |
2025-10-03 10:22:16.754655 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-10-03 10:22:16.754662 | controller | Friday 03 October 2025  10:22:10 +0000 (0:00:20.039)       0:06:31.487 ********
2025-10-03 10:22:16.754672 | controller | changed: [instance]
2025-10-03 10:22:17.885885 | controller |
2025-10-03 10:22:17.885916 | controller | TASK [Grab some info from the test node] ***************************************
2025-10-03 10:22:17.885924 | controller | Friday 03 October 2025  10:22:16 +0000 (0:00:06.551)       0:06:38.039 ********
2025-10-03 10:22:17.885934 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-03 10:22:18.991025 | controller |
2025-10-03 10:22:18.991059 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-10-03 10:22:18.991067 | controller | Friday 03 October 2025  10:22:17 +0000 (0:00:01.131)       0:06:39.170 ********
2025-10-03 10:22:18.991078 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-03 10:22:19.611169 | controller |
2025-10-03 10:22:19.611205 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-10-03 10:22:19.611213 | controller | Friday 03 October 2025  10:22:18 +0000 (0:00:01.105)       0:06:40.275 ********
2025-10-03 10:22:19.611223 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-03 10:22:20.117733 | controller |
2025-10-03 10:22:20.117762 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-10-03 10:22:20.117770 | controller | Friday 03 October 2025  10:22:19 +0000 (0:00:00.620)       0:06:40.895 ********
2025-10-03 10:22:20.117780 | controller | changed: [instance]
2025-10-03 10:22:20.454344 | controller |
2025-10-03 10:22:20.454376 | controller | TASK [Write test-node info to file] ********************************************
2025-10-03 10:22:20.454384 | controller | Friday 03 October 2025  10:22:20 +0000 (0:00:00.506)       0:06:41.402 ********
2025-10-03 10:22:20.454395 | controller | changed: [instance]
2025-10-03 10:22:20.791024 | controller |
2025-10-03 10:22:20.791057 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-10-03 10:22:20.791065 | controller | Friday 03 October 2025  10:22:20 +0000 (0:00:00.336)       0:06:41.738 ********
2025-10-03 10:22:20.791075 | controller | changed: [instance]
2025-10-03 10:22:21.135997 | controller |
2025-10-03 10:22:21.136060 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-10-03 10:22:21.136072 | controller | Friday 03 October 2025  10:22:20 +0000 (0:00:00.336)       0:06:42.075 ********
2025-10-03 10:22:21.136123 | controller | changed: [instance]
2025-10-03 10:22:21.505156 | controller |
2025-10-03 10:22:21.505187 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-10-03 10:22:21.505195 | controller | Friday 03 October 2025  10:22:21 +0000 (0:00:00.343)       0:06:42.419 ********
2025-10-03 10:22:21.505205 | controller | changed: [instance]
2025-10-03 10:22:21.505227 | controller |
2025-10-03 10:22:21.505236 | controller | TASK [Write hypervisor info to file] *******************************************
2025-10-03 10:22:21.505359 | controller | Friday 03 October 2025  10:22:21 +0000 (0:00:00.370)       0:06:42.789 ********
2025-10-03 10:22:21.870572 | controller | changed: [instance]
2025-10-03 10:22:23.565796 | controller |
2025-10-03 10:22:23.565828 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-10-03 10:22:23.565837 | controller | Friday 03 October 2025  10:22:21 +0000 (0:00:00.365)       0:06:43.155 ********
2025-10-03 10:22:23.565847 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-03 10:22:23.605196 | controller |
2025-10-03 10:22:23.605225 | controller | TASK [Debug the ping example.com result] ***************************************
2025-10-03 10:22:23.605234 | controller | Friday 03 October 2025  10:22:23 +0000 (0:00:01.695)       0:06:44.850 ********
2025-10-03 10:22:23.605246 | controller | ok: [instance] => (item=0) =>
2025-10-03 10:22:23.605276 | controller |   msg: '0'
2025-10-03 10:22:23.605426 | controller | ok: [instance] => (item=['PING example.com(a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450)) 56 data bytes', '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=1 ttl=47 time=42.4 ms', '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=41.5 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 41.547/41.984/42.422/0.437 ms']) =>
2025-10-03 10:22:23.607136 | controller |   msg:
2025-10-03 10:22:23.608131 | controller |   - PING example.com(a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450)) 56 data bytes
2025-10-03 10:22:23.608149 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=1 ttl=47 time=42.4 ms'
2025-10-03 10:22:23.608157 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=41.5 ms'
2025-10-03 10:22:23.608163 | controller |   - ''
2025-10-03 10:22:23.608169 | controller |   - '--- example.com ping statistics ---'
2025-10-03 10:22:23.608175 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-10-03 10:22:23.608181 | controller |   - rtt min/avg/max/mdev = 41.547/41.984/42.422/0.437 ms
2025-10-03 10:22:23.608186 | controller | ok: [instance] => (item=[]) =>
2025-10-03 10:22:23.608192 | controller |   msg: []
2025-10-03 10:22:23.608198 | controller |
2025-10-03 10:22:23.608203 | controller | PLAY RECAP *********************************************************************
2025-10-03 10:22:23.608209 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-10-03 10:22:23.608214 | controller |
2025-10-03 10:22:23.608220 | controller | Friday 03 October 2025  10:22:23 +0000 (0:00:00.039)       0:06:44.890 ********
2025-10-03 10:22:23.608225 | controller | ===============================================================================
2025-10-03 10:22:23.608231 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 259.87s
2025-10-03 10:22:23.608239 | controller | Wait for test node to be reachable via ssh ----------------------------- 28.74s
2025-10-03 10:22:23.608297 | controller | Download latest image -------------------------------------------------- 20.89s
2025-10-03 10:22:23.608311 | controller | Wait a little to let the test instance boot. --------------------------- 20.04s
2025-10-03 10:22:23.608317 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir --------------- 9.92s
2025-10-03 10:22:23.608329 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.26s
2025-10-03 10:22:23.608335 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.06s
2025-10-03 10:22:23.608341 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.48s
2025-10-03 10:22:23.608346 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.55s
2025-10-03 10:22:23.608351 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.55s
2025-10-03 10:22:23.608357 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.70s
2025-10-03 10:22:23.608365 | controller | discover_latest_image : Get latest image -------------------------------- 1.58s
2025-10-03 10:22:23.608416 | controller | config_drive : Install required RPM packages ---------------------------- 1.35s
2025-10-03 10:22:23.608530 | controller | config_drive : Install required RPM packages ---------------------------- 1.28s
2025-10-03 10:22:23.608662 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.19s
2025-10-03 10:22:23.608781 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.16s
2025-10-03 10:22:23.608886 | controller | Grab some info from the test node --------------------------------------- 1.13s
2025-10-03 10:22:23.608994 | controller | Grab some info from the nat64 appliance --------------------------------- 1.11s
2025-10-03 10:22:23.609123 | controller | nat64_appliance : Restart firewalld.service ----------------------------- 0.95s
2025-10-03 10:22:23.609241 | controller | Restart firewalld.service ----------------------------------------------- 0.95s
2025-10-03 10:22:23.669929 | controller | INFO     Running default > cleanup
2025-10-03 10:22:24.122190 | controller |
2025-10-03 10:22:25.042228 | controller | PLAY [Cleanup] *****************************************************************
2025-10-03 10:22:25.042261 | controller |
2025-10-03 10:22:25.042269 | controller | TASK [Gathering Facts] *********************************************************
2025-10-03 10:22:25.042275 | controller | Friday 03 October 2025  10:22:24 +0000 (0:00:00.045)       0:00:00.045 ********
2025-10-03 10:22:25.042285 | controller | ok: [instance]
2025-10-03 10:22:25.594687 | controller |
2025-10-03 10:22:25.594719 | controller | TASK [Destroy the test-node] ***************************************************
2025-10-03 10:22:25.594727 | controller | Friday 03 October 2025  10:22:25 +0000 (0:00:00.920)       0:00:00.966 ********
2025-10-03 10:22:25.594737 | controller | ok: [instance]
2025-10-03 10:22:25.823181 | controller |
2025-10-03 10:22:25.823218 | controller | TASK [Undefine the test-node] **************************************************
2025-10-03 10:22:25.823226 | controller | Friday 03 October 2025  10:22:25 +0000 (0:00:00.552)       0:00:01.518 ********
2025-10-03 10:22:25.823237 | controller | ok: [instance]
2025-10-03 10:22:25.823262 | controller |
2025-10-03 10:22:25.823271 | controller | TASK [Destroy the test network] ************************************************
2025-10-03 10:22:25.823292 | controller | Friday 03 October 2025  10:22:25 +0000 (0:00:00.228)       0:00:01.747 ********
2025-10-03 10:22:26.209948 | controller | ok: [instance]
2025-10-03 10:22:26.428710 | controller |
2025-10-03 10:22:26.428739 | controller | TASK [Undefine the test network] ***********************************************
2025-10-03 10:22:26.428747 | controller | Friday 03 October 2025  10:22:26 +0000 (0:00:00.386)       0:00:02.134 ********
2025-10-03 10:22:26.428757 | controller | ok: [instance]
2025-10-03 10:22:26.460104 | controller |
2025-10-03 10:22:26.460131 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-10-03 10:22:26.460139 | controller | Friday 03 October 2025  10:22:26 +0000 (0:00:00.218)       0:00:02.352 ********
2025-10-03 10:22:26.460149 | controller |
2025-10-03 10:22:26.771860 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-10-03 10:22:26.771896 | controller | Friday 03 October 2025  10:22:26 +0000 (0:00:00.031)       0:00:02.384 ********
2025-10-03 10:22:26.771909 | controller | changed: [instance]
2025-10-03 10:22:27.055044 | controller |
2025-10-03 10:22:27.055074 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-10-03 10:22:27.055102 | controller | Friday 03 October 2025  10:22:26 +0000 (0:00:00.311)       0:00:02.696 ********
2025-10-03 10:22:27.055122 | controller | ok: [instance]
2025-10-03 10:22:27.277131 | controller |
2025-10-03 10:22:27.277160 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-10-03 10:22:27.277169 | controller | Friday 03 October 2025  10:22:27 +0000 (0:00:00.283)       0:00:02.979 ********
2025-10-03 10:22:27.277179 | controller | ok: [instance]
2025-10-03 10:22:27.921920 | controller |
2025-10-03 10:22:27.921949 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-10-03 10:22:27.921957 | controller | Friday 03 October 2025  10:22:27 +0000 (0:00:00.222)       0:00:03.201 ********
2025-10-03 10:22:27.921967 | controller | ok: [instance]
2025-10-03 10:22:28.154729 | controller |
2025-10-03 10:22:28.154760 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-10-03 10:22:28.154768 | controller | Friday 03 October 2025  10:22:27 +0000 (0:00:00.644)       0:00:03.846 ********
2025-10-03 10:22:28.154778 | controller | ok: [instance]
2025-10-03 10:22:28.933704 | controller |
2025-10-03 10:22:28.933746 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-10-03 10:22:28.933755 | controller | Friday 03 October 2025  10:22:28 +0000 (0:00:00.232)       0:00:04.079 ********
2025-10-03 10:22:28.933765 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-03 10:22:29.396232 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-03 10:22:29.396273 | controller |
2025-10-03 10:22:29.396283 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-10-03 10:22:29.396290 | controller | Friday 03 October 2025  10:22:28 +0000 (0:00:00.778)       0:00:04.857 ********
2025-10-03 10:22:29.396303 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-03 10:22:29.396334 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-03 10:22:29.396342 | controller |
2025-10-03 10:22:29.396349 | controller | PLAY RECAP *********************************************************************
2025-10-03 10:22:29.396356 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-10-03 10:22:29.396362 | controller |
2025-10-03 10:22:29.396369 | controller | Friday 03 October 2025  10:22:29 +0000 (0:00:00.462)       0:00:05.320 ********
2025-10-03 10:22:29.396376 | controller | ===============================================================================
2025-10-03 10:22:29.396383 | controller | Gathering Facts --------------------------------------------------------- 0.92s
2025-10-03 10:22:29.396390 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.78s
2025-10-03 10:22:29.396396 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.64s
2025-10-03 10:22:29.396405 | controller | Destroy the test-node --------------------------------------------------- 0.55s
2025-10-03 10:22:29.396431 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.46s
2025-10-03 10:22:29.396455 | controller | Destroy the test network ------------------------------------------------ 0.39s
2025-10-03 10:22:29.396800 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.31s
2025-10-03 10:22:29.397298 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.28s
2025-10-03 10:22:29.397335 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.23s
2025-10-03 10:22:29.447814 | controller | Undefine the test-node -------------------------------------------------- 0.23s
2025-10-03 10:22:29.447848 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.22s
2025-10-03 10:22:29.447855 | controller | Undefine the test network ----------------------------------------------- 0.22s
2025-10-03 10:22:29.447861 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-10-03 10:22:29.447871 | controller | INFO     Writing /tmp/report.html report.
2025-10-03 10:22:29.831830 | [controller] Waiting on logger
2025-10-03 10:22:34.994524 | [controller] Waiting on logger
2025-10-03 10:22:45.426414 | [controller] Waiting on logger
2025-10-03 10:22:55.858439 | [controller] Waiting on logger
2025-10-03 10:22:59.528597 | [Zuul] Log Stream did not terminate
2025-10-03 10:22:59.528772 | controller | changed
2025-10-03 10:22:59.551408 | 
2025-10-03 10:22:59.551479 | PLAY RECAP
2025-10-03 10:22:59.551527 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-03 10:22:59.551555 | 
2025-10-03 10:22:59.614812 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-03 10:22:59.615842 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-03 10:23:00.170155 | 
2025-10-03 10:23:00.170266 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-10-03 10:23:00.190675 | 
2025-10-03 10:23:00.190764 | TASK [Filter out host if needed]
2025-10-03 10:23:00.199391 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-10-03 10:23:00.203801 | 
2025-10-03 10:23:00.203870 | TASK [Ensure file is present]
2025-10-03 10:23:00.530693 | controller | ok
2025-10-03 10:23:00.537425 | 
2025-10-03 10:23:00.537510 | TASK [Manage molecule report file]
2025-10-03 10:23:00.567130 | [controller] Waiting on logger
2025-10-03 10:23:09.911042 | [controller] Waiting on logger
2025-10-03 10:23:20.306321 | [controller] Waiting on logger
2025-10-03 10:23:30.738343 | [controller] Waiting on logger
2025-10-03 10:23:30.882186 | [Zuul] Log Stream did not terminate
2025-10-03 10:23:30.882354 | controller | changed
2025-10-03 10:23:30.887474 | 
2025-10-03 10:23:30.887537 | TASK [Check if we get ci-framework-data basedir]
2025-10-03 10:23:31.078898 | controller | ok
2025-10-03 10:23:31.084165 | 
2025-10-03 10:23:31.084252 | TASK [Create ci-framework-data log directory for zuul]
2025-10-03 10:23:31.399349 | controller | changed
2025-10-03 10:23:31.404574 | 
2025-10-03 10:23:31.404677 | TASK [Copy ci-framework interesting files]
2025-10-03 10:23:36.435209 | controller | changed
2025-10-03 10:23:36.440586 | 
2025-10-03 10:23:36.440677 | TASK [Get SELinux listing]
2025-10-03 10:23:36.460982 | [controller] Waiting on logger
2025-10-03 10:23:42.130414 | [controller] Waiting on logger
2025-10-03 10:23:42.691347 | controller | changed
2025-10-03 10:23:42.697070 | 
2025-10-03 10:23:42.697147 | TASK [Generate log index]
2025-10-03 10:23:43.313404 | controller | changed
2025-10-03 10:23:43.318272 | 
2025-10-03 10:23:43.318407 | TASK [Get some env related data]
2025-10-03 10:23:44.370399 | [controller] Waiting on logger
2025-10-03 10:23:55.080283 | controller | changed
2025-10-03 10:23:55.085444 | 
2025-10-03 10:23:55.085508 | TASK [Generate list of logs to collect in home directory]
2025-10-03 10:23:55.367057 | controller | ok: All paths examined
2025-10-03 10:23:55.372220 | 
2025-10-03 10:23:55.372288 | LOOP [Copy logs from home directory]
2025-10-03 10:23:55.687719 | controller | changed:
2025-10-03 10:23:55.687829 | controller | {
2025-10-03 10:23:55.687856 | controller |   "atime": 1759486329.8043222,
2025-10-03 10:23:55.687876 | controller |   "ctime": 1759486351.3993878,
2025-10-03 10:23:55.687893 | controller |   "dev": 64513,
2025-10-03 10:23:55.687931 | controller |   "gid": 1000,
2025-10-03 10:23:55.687953 | controller |   "gr_name": "zuul",
2025-10-03 10:23:55.687970 | controller |   "inode": 4450877,
2025-10-03 10:23:55.687985 | controller |   "isblk": false,
2025-10-03 10:23:55.688000 | controller |   "ischr": false,
2025-10-03 10:23:55.688014 | controller |   "isdir": false,
2025-10-03 10:23:55.688029 | controller |   "isfifo": false,
2025-10-03 10:23:55.688044 | controller |   "isgid": false,
2025-10-03 10:23:55.688058 | controller |   "islnk": false,
2025-10-03 10:23:55.688073 | controller |   "isreg": true,
2025-10-03 10:23:55.688094 | controller |   "issock": false,
2025-10-03 10:23:55.688109 | controller |   "isuid": false,
2025-10-03 10:23:55.688124 | controller |   "mode": "0644",
2025-10-03 10:23:55.688140 | controller |   "mtime": 1759486351.3993878,
2025-10-03 10:23:55.688155 | controller |   "nlink": 1,
2025-10-03 10:23:55.688170 | controller |   "path": "/home/zuul/ansible.log",
2025-10-03 10:23:55.688184 | controller |   "pw_name": "zuul",
2025-10-03 10:23:55.688199 | controller |   "rgrp": true,
2025-10-03 10:23:55.688216 | controller |   "roth": true,
2025-10-03 10:23:55.688231 | controller |   "rusr": true,
2025-10-03 10:23:55.688245 | controller |   "size": 6749,
2025-10-03 10:23:55.688258 | controller |   "uid": 1000,
2025-10-03 10:23:55.688271 | controller |   "wgrp": false,
2025-10-03 10:23:55.688285 | controller |   "woth": false,
2025-10-03 10:23:55.688298 | controller |   "wusr": true,
2025-10-03 10:23:55.688312 | controller |   "xgrp": false,
2025-10-03 10:23:55.688326 | controller |   "xoth": false,
2025-10-03 10:23:55.688340 | controller |   "xusr": false
2025-10-03 10:23:55.688354 | controller | }
2025-10-03 10:23:55.700829 | 
2025-10-03 10:23:55.700891 | TASK [Copy crio stats log file]
2025-10-03 10:23:55.714249 | controller | skipping: Conditional result was False
2025-10-03 10:23:55.719453 | 
2025-10-03 10:23:55.719520 | TASK [Get SELinux related data]
2025-10-03 10:23:57.746458 | [controller] Waiting on logger
2025-10-03 10:23:58.834379 | [controller] Waiting on logger
2025-10-03 10:24:16.370404 | [controller] Waiting on logger
2025-10-03 10:24:18.546295 | [controller] Waiting on logger
2025-10-03 10:24:25.960313 | [Zuul] Log Stream did not terminate
2025-10-03 10:24:25.960489 | controller | ERROR
2025-10-03 10:24:25.960581 | controller | {
2025-10-03 10:24:25.960610 | controller |   "delta": "0:00:00.008729",
2025-10-03 10:24:25.960631 | controller |   "end": "2025-10-03 10:23:55.932969",
2025-10-03 10:24:25.960660 | controller |   "msg": "non-zero return code",
2025-10-03 10:24:25.960679 | controller |   "rc": 1,
2025-10-03 10:24:25.960697 | controller |   "start": "2025-10-03 10:23:55.924240"
2025-10-03 10:24:25.960713 | controller | }
2025-10-03 10:24:25.960736 | controller | ERROR: Ignoring Errors
2025-10-03 10:24:25.966098 | 
2025-10-03 10:24:25.966166 | TASK [Create system configuration directory]
2025-10-03 10:24:26.166359 | controller | changed
2025-10-03 10:24:26.171391 | 
2025-10-03 10:24:26.171458 | TASK [Get some of the system configurations]
2025-10-03 10:24:27.250447 | [controller] Waiting on logger
2025-10-03 10:24:42.226381 | [controller] Waiting on logger
2025-10-03 10:24:50.657150 | controller | changed
2025-10-03 10:24:50.662274 | 
2025-10-03 10:24:50.662340 | TASK [Copy generated documentation if available]
2025-10-03 10:24:50.675475 | controller | skipping: Conditional result was False
2025-10-03 10:24:50.681121 | 
2025-10-03 10:24:50.681187 | TASK [Copy generated AsciiDoc documentation if available]
2025-10-03 10:24:50.694549 | controller | skipping: Conditional result was False
2025-10-03 10:24:50.700458 | 
2025-10-03 10:24:50.700522 | TASK [Compress logs bigger than 2MB]
2025-10-03 10:24:54.706390 | [controller] Waiting on logger
2025-10-03 10:24:55.724576 | controller | changed
2025-10-03 10:24:55.729905 | 
2025-10-03 10:24:55.729991 | TASK [Copy files from workspace on node]
2025-10-03 10:24:55.747975 | controller | ok
2025-10-03 10:24:55.770628 | 
2025-10-03 10:24:55.770723 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-03 10:24:55.784129 | controller | skipping: Conditional result was False
2025-10-03 10:24:55.789524 | 
2025-10-03 10:24:55.789598 | TASK [fetch-output : Set log path for single node]
2025-10-03 10:24:55.817803 | controller | ok
2025-10-03 10:24:55.823795 | 
2025-10-03 10:24:55.823869 | LOOP [fetch-output : Ensure local output dirs]
2025-10-03 10:24:56.026186 | controller -> localhost | ok: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/logs"
2025-10-03 10:24:56.026436 | controller -> localhost | changed: All items complete
2025-10-03 10:24:56.026480 | 
2025-10-03 10:24:56.208028 | controller -> localhost | changed: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/artifacts"
2025-10-03 10:24:56.386832 | controller -> localhost | changed: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/docs"
2025-10-03 10:24:56.401492 | 
2025-10-03 10:24:56.401592 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-03 10:24:56.979145 | controller | changed:
2025-10-03 10:24:56.979326 | controller | .d..t...... ./
2025-10-03 10:24:56.979358 | controller | >f+++++++++ README.html
2025-10-03 10:24:56.979379 | controller | >f+++++++++ ansible-execution.log
2025-10-03 10:24:56.979398 | controller | >f+++++++++ ansible.log
2025-10-03 10:24:56.979415 | controller | >f+++++++++ dmesg.log
2025-10-03 10:24:56.979433 | controller | >f+++++++++ installed-pkgs.log
2025-10-03 10:24:56.979450 | controller | >f+++++++++ python.log
2025-10-03 10:24:56.979465 | controller | >f+++++++++ registries.conf
2025-10-03 10:24:56.979480 | controller | >f+++++++++ report.html
2025-10-03 10:24:56.979495 | controller | >f+++++++++ selinux-denials.log
2025-10-03 10:24:56.979511 | controller | >f+++++++++ selinux-listing.log
2025-10-03 10:24:56.979526 | controller | cd+++++++++ ci-framework-data/
2025-10-03 10:24:56.979542 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-10-03 10:24:56.979558 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-10-03 10:24:56.979574 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-10-03 10:24:56.979588 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-10-03 10:24:56.979603 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-10-03 10:24:56.979618 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-10-03 10:24:56.979632 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/aed03b07-e337-5645-8814-6bda1b87e43a/
2025-10-03 10:24:56.979659 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/aed03b07-e337-5645-8814-6bda1b87e43a/meta-data
2025-10-03 10:24:56.979676 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/aed03b07-e337-5645-8814-6bda1b87e43a/network-config
2025-10-03 10:24:56.979691 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/aed03b07-e337-5645-8814-6bda1b87e43a/user-data
2025-10-03 10:24:56.979707 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f8ff43be-947c-5898-ab2e-f2859e0a0f68/
2025-10-03 10:24:56.979721 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f8ff43be-947c-5898-ab2e-f2859e0a0f68/meta-data
2025-10-03 10:24:56.979737 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f8ff43be-947c-5898-ab2e-f2859e0a0f68/network-config
2025-10-03 10:24:56.979752 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f8ff43be-947c-5898-ab2e-f2859e0a0f68/user-data
2025-10-03 10:24:56.979766 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-10-03 10:24:56.979781 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-10-03 10:24:56.979795 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-10-03 10:24:56.979809 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-10-03 10:24:56.979823 | controller | cd+++++++++ ci-framework-data/logs/
2025-10-03 10:24:56.979837 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-03 10:24:56.979850 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-03 10:24:56.979864 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-03 10:24:56.979877 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-10-03 10:24:56.979890 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-10-03 10:24:56.979930 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-10-03 10:24:56.979956 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-10-03 10:24:56.979974 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-10-03 10:24:56.979989 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-10-03 10:24:56.980004 | controller | cd+++++++++ registries.conf.d/
2025-10-03 10:24:56.980018 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-10-03 10:24:56.980033 | controller | cd+++++++++ system-config/
2025-10-03 10:24:56.980048 | controller | cd+++++++++ system-config/libvirt/
2025-10-03 10:24:56.980062 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-10-03 10:24:56.980077 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-10-03 10:24:56.980091 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-10-03 10:24:56.980104 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-10-03 10:24:56.980117 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-10-03 10:24:56.980130 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-10-03 10:24:56.980143 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-10-03 10:24:56.980156 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-10-03 10:24:56.980169 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-10-03 10:24:56.980182 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-10-03 10:24:56.980195 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-10-03 10:24:56.980209 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-10-03 10:24:56.980222 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-10-03 10:24:56.980235 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-10-03 10:24:56.980248 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-10-03 10:24:56.980261 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-10-03 10:24:57.352235 | controller | changed: .d..t...... ./
2025-10-03 10:24:57.723164 | controller | changed: .d..t...... ./
2025-10-03 10:24:57.742260 | 
2025-10-03 10:24:57.742366 | TASK [Return artifact to Zuul]
2025-10-03 10:24:57.770589 | controller | ok
2025-10-03 10:24:57.789503 | 
2025-10-03 10:24:57.789558 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-10-03 10:24:57.789674 | 
2025-10-03 10:24:57.789707 | PLAY RECAP
2025-10-03 10:24:57.789755 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-10-03 10:24:57.789778 | 
2025-10-03 10:24:57.872953 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-03 10:24:57.873676 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-03 10:24:58.394783 | 
2025-10-03 10:24:58.394892 | PLAY [all]
2025-10-03 10:24:58.413483 | 
2025-10-03 10:24:58.413562 | TASK [include_role : fetch-output]
2025-10-03 10:24:58.441935 | controller | ok
2025-10-03 10:24:58.459638 | 
2025-10-03 10:24:58.459764 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-03 10:24:58.503967 | controller | skipping: Conditional result was False
2025-10-03 10:24:58.509607 | 
2025-10-03 10:24:58.509702 | TASK [fetch-output : Set log path for single node]
2025-10-03 10:24:58.537792 | controller | ok
2025-10-03 10:24:58.542830 | 
2025-10-03 10:24:58.542902 | LOOP [fetch-output : Ensure local output dirs]
2025-10-03 10:24:58.861939 | controller -> localhost | ok: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/logs"
2025-10-03 10:24:59.048270 | controller -> localhost | ok: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/artifacts"
2025-10-03 10:24:59.233323 | controller -> localhost | ok: "/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/docs"
2025-10-03 10:24:59.246143 | 
2025-10-03 10:24:59.246255 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-03 10:24:59.761934 | controller | ok
2025-10-03 10:24:59.762127 | controller | ok: All items complete
2025-10-03 10:24:59.762158 | 
2025-10-03 10:25:00.126776 | controller | ok
2025-10-03 10:25:00.482722 | controller | ok
2025-10-03 10:25:00.494165 | 
2025-10-03 10:25:00.494308 | TASK [include_role : fetch-output-openshift]
2025-10-03 10:25:00.507703 | controller | skipping: Conditional result was False
2025-10-03 10:25:00.513295 | 
2025-10-03 10:25:00.513383 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-03 10:25:00.854356 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006210
2025-10-03 10:25:01.043666 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006259
2025-10-03 10:25:01.077220 | 
2025-10-03 10:25:01.077279 | PLAY [all]
2025-10-03 10:25:01.090738 | 
2025-10-03 10:25:01.090806 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-03 10:25:01.484967 | controller | changed
2025-10-03 10:25:01.505593 | 
2025-10-03 10:25:01.505663 | PLAY RECAP
2025-10-03 10:25:01.505708 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-03 10:25:01.505731 | 
2025-10-03 10:25:01.573335 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-03 10:25:01.574115 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-03 10:25:02.128293 | 
2025-10-03 10:25:02.128401 | PLAY [localhost]
2025-10-03 10:25:02.146201 | 
2025-10-03 10:25:02.146283 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-03 10:25:02.447628 | localhost | changed
2025-10-03 10:25:02.452306 | 
2025-10-03 10:25:02.452413 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-03 10:25:02.473074 | localhost | ok
2025-10-03 10:25:02.481246 | 
2025-10-03 10:25:02.481326 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-03 10:25:02.773186 | localhost | changed
2025-10-03 10:25:02.779124 | 
2025-10-03 10:25:02.779227 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-03 10:25:03.316801 | localhost | changed
2025-10-03 10:25:03.321778 | 
2025-10-03 10:25:03.321867 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-03 10:25:03.643128 | localhost | Identity added: /var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/tmp/ansible.83g18518 (/var/lib/zuul/builds/0448881d65974fc096ecbac67381707a/work/tmp/ansible.83g18518)
2025-10-03 10:25:03.643291 | localhost | ok: Runtime: 0:00:00.005783
2025-10-03 10:25:03.647441 | 
2025-10-03 10:25:03.647515 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-03 10:25:03.867081 | localhost | ok: Runtime: 0:00:00.004181
2025-10-03 10:25:03.871627 | 
2025-10-03 10:25:03.871723 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-03 10:25:03.919245 | localhost | changed
2025-10-03 10:25:03.924230 | 
2025-10-03 10:25:03.924316 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-03 10:25:04.235761 | localhost | changed
2025-10-03 10:25:04.254871 | 
2025-10-03 10:25:04.254955 | PLAY [localhost]
2025-10-03 10:25:04.266520 | 
2025-10-03 10:25:04.266585 | TASK [Generate bulk log download script]
2025-10-03 10:25:04.284366 | localhost | ok
2025-10-03 10:25:04.295842 | 
2025-10-03 10:25:04.295932 | TASK [local-log-download : Check API endpoint is defined]
2025-10-03 10:25:04.322906 | localhost | ok: All assertions passed
2025-10-03 10:25:04.327192 | 
2025-10-03 10:25:04.327267 | TASK [local-log-download : Create download script]
2025-10-03 10:25:04.674289 | localhost -> localhost | changed
2025-10-03 10:25:04.682742 | 
2025-10-03 10:25:04.682816 | TASK [Register quick-download link]
2025-10-03 10:25:04.700000 | localhost | ok
2025-10-03 10:25:04.734438 | 
2025-10-03 10:25:04.734517 | PLAY [logserver.rdoproject.org]
2025-10-03 10:25:04.743728 | 
2025-10-03 10:25:04.743857 | TASK [Set zuul-log-path fact]
2025-10-03 10:25:04.759196 | logserver.rdoproject.org | ok
2025-10-03 10:25:04.768200 | 
2025-10-03 10:25:04.768267 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 10:25:04.793841 | logserver.rdoproject.org | ok
2025-10-03 10:25:04.799225 | 
2025-10-03 10:25:04.799298 | TASK [upload-logs : Create log directories]
2025-10-03 10:25:06.536233 | logserver.rdoproject.org | changed
2025-10-03 10:25:06.539667 | 
2025-10-03 10:25:06.539735 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-03 10:25:06.766130 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004781
2025-10-03 10:25:06.770630 | 
2025-10-03 10:25:06.770712 | TASK [upload-logs : Upload logs to log server]
2025-10-03 10:25:08.324403 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-03 10:25:08.327144 | 
2025-10-03 10:25:08.327206 | LOOP [upload-logs : Compress console log and json output]
2025-10-03 10:25:08.362611 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:25:08.370754 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:25:08.383933 | 
2025-10-03 10:25:08.384006 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-03 10:25:08.419547 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:25:08.419743 | 
2025-10-03 10:25:08.423276 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:25:08.430443 | 
2025-10-03 10:25:08.430513 | LOOP [upload-logs : Upload console log and json output]