2025-12-11 15:30:23.608841 | Job console starting...
2025-12-11 15:30:23.821682 | Updating repositories
2025-12-11 15:30:24.591583 | Preparing job workspace
2025-12-11 15:30:31.539355 | Running Ansible setup...
2025-12-11 15:30:34.169282 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-11 15:30:34.666230 | 
2025-12-11 15:30:34.666342 | PLAY [localhost]
2025-12-11 15:30:34.674732 | 
2025-12-11 15:30:34.674815 | TASK [Gathering Facts]
2025-12-11 15:30:35.460194 | localhost | ok
2025-12-11 15:30:35.471889 | 
2025-12-11 15:30:35.471979 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-11 15:30:35.758504 | localhost -> localhost | changed
2025-12-11 15:30:35.763525 | 
2025-12-11 15:30:35.763596 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-11 15:30:36.383324 | localhost -> localhost | changed
2025-12-11 15:30:36.391448 | 
2025-12-11 15:30:36.391532 | TASK [Setup log path fact]
2025-12-11 15:30:36.407906 | localhost | ok
2025-12-11 15:30:36.417950 | 
2025-12-11 15:30:36.418020 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-11 15:30:36.434811 | localhost | ok
2025-12-11 15:30:36.441404 | 
2025-12-11 15:30:36.441467 | TASK [emit-job-header : Print job information]
2025-12-11 15:30:36.467122 | # Job Information
2025-12-11 15:30:36.467233 | Ansible Version: 2.15.12
2025-12-11 15:30:36.467261 | Job: cifmw-molecule-nat64_appliance
2025-12-11 15:30:36.467283 | Pipeline: github-check
2025-12-11 15:30:36.467311 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-12-11 15:30:36.467331 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3545
2025-12-11 15:30:36.467350 | Log URL (when completed): https://logserver.rdoproject.org/22a/rdoproject.org/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/
2025-12-11 15:30:36.467368 | Event ID: 2e33fe80-d6a6-11f0-981e-769810e78078
2025-12-11 15:30:36.470686 | 
2025-12-11 15:30:36.470747 | LOOP [emit-job-header : Print node information]
2025-12-11 15:30:36.546999 | localhost | ok:
2025-12-11 15:30:36.547166 | localhost | # Node Information
2025-12-11 15:30:36.547195 | localhost | Inventory Hostname: controller
2025-12-11 15:30:36.547218 | localhost | Hostname: np0005555726
2025-12-11 15:30:36.547237 | localhost | Username: zuul
2025-12-11 15:30:36.547256 | localhost | Distro: CentOS 9
2025-12-11 15:30:36.547272 | localhost | Provider: ibm-bm4-nodepool
2025-12-11 15:30:36.547287 | localhost | Region: regionOne
2025-12-11 15:30:36.547316 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-12-11 15:30:36.547332 | localhost | Product Name: OpenStack Compute
2025-12-11 15:30:36.547347 | localhost | Interface IP: 192.168.26.235
2025-12-11 15:30:36.570832 | 
2025-12-11 15:30:36.570924 | PLAY [all]
2025-12-11 15:30:36.576737 | 
2025-12-11 15:30:36.576794 | TASK [Gather network facts]
2025-12-11 15:30:36.898898 | controller | ok
2025-12-11 15:30:36.911884 | 
2025-12-11 15:30:36.911984 | TASK [include_role : start-zuul-console]
2025-12-11 15:30:36.928390 | controller | ok
2025-12-11 15:30:36.939099 | 
2025-12-11 15:30:36.939159 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-11 15:30:37.209829 | controller | ok
2025-12-11 15:30:37.217406 | 
2025-12-11 15:30:37.217463 | TASK [include_role : add-build-sshkey]
2025-12-11 15:30:37.234415 | controller | ok
2025-12-11 15:30:37.246387 | 
2025-12-11 15:30:37.246455 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-11 15:30:37.431121 | controller -> localhost | ok
2025-12-11 15:30:37.435801 | 
2025-12-11 15:30:37.435860 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-11 15:30:37.452165 | controller | ok
2025-12-11 15:30:37.464482 | controller | included: /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-11 15:30:37.469569 | 
2025-12-11 15:30:37.469631 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-11 15:30:37.826415 | controller -> localhost | Generating public/private rsa key pair.
2025-12-11 15:30:37.826580 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/22aab5ab0d604d9fa8ec4fd2c4f9ac3b_id_rsa.
2025-12-11 15:30:37.826611 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/22aab5ab0d604d9fa8ec4fd2c4f9ac3b_id_rsa.pub.
2025-12-11 15:30:37.826634 | controller -> localhost | The key fingerprint is:
2025-12-11 15:30:37.826654 | controller -> localhost | SHA256:ZguXoAJ5nK7P8HH46r8vYjzvyjK46eSDRSfmHuJhlnk zuul-build-sshkey
2025-12-11 15:30:37.826673 | controller -> localhost | The key's randomart image is:
2025-12-11 15:30:37.826691 | controller -> localhost | +---[RSA 3072]----+
2025-12-11 15:30:37.826709 | controller -> localhost | |                 |
2025-12-11 15:30:37.826727 | controller -> localhost | | o .             |
2025-12-11 15:30:37.826744 | controller -> localhost | |o +   .          |
2025-12-11 15:30:37.826762 | controller -> localhost | | ++ .. . .       |
2025-12-11 15:30:37.826780 | controller -> localhost | | +=o. . S        |
2025-12-11 15:30:37.826797 | controller -> localhost | |.B+E   = .       |
2025-12-11 15:30:37.826815 | controller -> localhost | |O*=..   .        |
2025-12-11 15:30:37.826832 | controller -> localhost | |BX*+.            |
2025-12-11 15:30:37.826850 | controller -> localhost | |+OXO*+.          |
2025-12-11 15:30:37.826867 | controller -> localhost | +----[SHA256]-----+
2025-12-11 15:30:37.826907 | controller -> localhost | ok: Runtime: 0:00:00.055224
2025-12-11 15:30:37.832295 | 
2025-12-11 15:30:37.832355 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-11 15:30:37.849182 | controller | ok
2025-12-11 15:30:37.858047 | controller | included: /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-11 15:30:37.865880 | 
2025-12-11 15:30:37.865963 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-11 15:30:37.879078 | controller | skipping: Conditional result was False
2025-12-11 15:30:37.883988 | 
2025-12-11 15:30:37.884047 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-11 15:30:38.224586 | controller | changed
2025-12-11 15:30:38.230088 | 
2025-12-11 15:30:38.230147 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-11 15:30:38.399459 | controller | ok
2025-12-11 15:30:38.404064 | 
2025-12-11 15:30:38.404127 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-11 15:30:38.908353 | controller | changed
2025-12-11 15:30:38.912716 | 
2025-12-11 15:30:38.912776 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-11 15:30:39.417555 | controller | changed
2025-12-11 15:30:39.422615 | 
2025-12-11 15:30:39.422676 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-11 15:30:39.435358 | controller | skipping: Conditional result was False
2025-12-11 15:30:39.440326 | 
2025-12-11 15:30:39.440393 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-11 15:30:39.726162 | controller -> localhost | changed
2025-12-11 15:30:39.736435 | 
2025-12-11 15:30:39.736498 | TASK [add-build-sshkey : Add back temp key]
2025-12-11 15:30:39.941220 | controller -> localhost | Identity added: /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/22aab5ab0d604d9fa8ec4fd2c4f9ac3b_id_rsa (zuul-build-sshkey)
2025-12-11 15:30:39.941386 | controller -> localhost | ok: Runtime: 0:00:00.006172
2025-12-11 15:30:39.946480 | 
2025-12-11 15:30:39.946539 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-11 15:30:40.196455 | controller | ok
2025-12-11 15:30:40.200487 | 
2025-12-11 15:30:40.200544 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-11 15:30:40.223461 | controller | skipping: Conditional result was False
2025-12-11 15:30:40.231985 | 
2025-12-11 15:30:40.232042 | TASK [include_role : validate-host]
2025-12-11 15:30:40.248638 | controller | ok
2025-12-11 15:30:40.266755 | 
2025-12-11 15:30:40.266822 | TASK [validate-host : Define zuul_info_dir fact]
2025-12-11 15:30:40.294302 | controller | ok
2025-12-11 15:30:40.298363 | 
2025-12-11 15:30:40.298420 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-12-11 15:30:40.482799 | controller -> localhost | ok
2025-12-11 15:30:40.487658 | 
2025-12-11 15:30:40.487718 | TASK [validate-host : Collect information about the host]
2025-12-11 15:30:41.054205 | controller | ok
2025-12-11 15:30:41.062126 | 
2025-12-11 15:30:41.062196 | TASK [validate-host : Sanitize hostname]
2025-12-11 15:30:41.099632 | controller | ok
2025-12-11 15:30:41.104313 | 
2025-12-11 15:30:41.104377 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-12-11 15:30:41.471516 | controller -> localhost | changed
2025-12-11 15:30:41.477960 | 
2025-12-11 15:30:41.478032 | TASK [validate-host : Collect information about zuul worker]
2025-12-11 15:30:41.789513 | controller | ok
2025-12-11 15:30:41.793595 | 
2025-12-11 15:30:41.793655 | TASK [validate-host : Write out all zuul information for each host]
2025-12-11 15:30:42.128699 | controller -> localhost | changed
2025-12-11 15:30:42.137064 | 
2025-12-11 15:30:42.137122 | TASK [include_role : prepare-workspace-openshift]
2025-12-11 15:30:42.149847 | controller | skipping: Conditional result was False
2025-12-11 15:30:42.154183 | 
2025-12-11 15:30:42.154243 | TASK [include_role : remove-zuul-sshkey]
2025-12-11 15:30:42.166564 | controller | skipping: Conditional result was False
2025-12-11 15:30:42.171247 | 
2025-12-11 15:30:42.171317 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-11 15:30:42.349397 | controller | ok: "logs"
2025-12-11 15:30:42.349661 | controller | ok: All items complete
2025-12-11 15:30:42.349694 | 
2025-12-11 15:30:42.507900 | controller | ok: "artifacts"
2025-12-11 15:30:42.659508 | controller | ok: "docs"
2025-12-11 15:30:42.666190 | 
2025-12-11 15:30:42.666307 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-11 15:30:42.856254 | controller | changed: "logs"
2025-12-11 15:30:43.019860 | controller | changed: "artifacts"
2025-12-11 15:30:43.174363 | controller | changed: "docs"
2025-12-11 15:30:43.200180 | 
2025-12-11 15:30:43.200241 | PLAY RECAP
2025-12-11 15:30:43.200297 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-12-11 15:30:43.200327 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-11 15:30:43.200346 | 
2025-12-11 15:30:43.282560 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-11 15:30:43.283342 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-12-11 15:30:43.790056 | 
2025-12-11 15:30:43.790210 | PLAY [all]
2025-12-11 15:30:43.809746 | 
2025-12-11 15:30:43.809822 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-12-11 15:30:43.859062 | controller | ok
2025-12-11 15:30:43.864026 | 
2025-12-11 15:30:43.864106 | TASK [mirror-info-fork : Create /etc/ci]
2025-12-11 15:30:44.166635 | controller | changed
2025-12-11 15:30:44.171518 | 
2025-12-11 15:30:44.171585 | TASK [mirror-info-fork : Install ci_mirror script]
2025-12-11 15:30:44.878445 | controller | changed
2025-12-11 15:30:44.887440 | 
2025-12-11 15:30:44.887502 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-12-11 15:30:45.210114 | controller | changed:
2025-12-11 15:30:45.210280 | controller | {
2025-12-11 15:30:45.210318 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-12-11 15:30:45.210346 | controller | }
2025-12-11 15:30:45.391777 | controller | changed:
2025-12-11 15:30:45.391826 | controller | {
2025-12-11 15:30:45.391852 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-12-11 15:30:45.391871 | controller | }
2025-12-11 15:30:45.576789 | controller | changed:
2025-12-11 15:30:45.576839 | controller | {
2025-12-11 15:30:45.576864 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-12-11 15:30:45.576883 | controller | }
2025-12-11 15:30:45.763175 | controller | changed:
2025-12-11 15:30:45.763224 | controller | {
2025-12-11 15:30:45.763248 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-12-11 15:30:45.763268 | controller | }
2025-12-11 15:30:45.949272 | controller | changed:
2025-12-11 15:30:45.949340 | controller | {
2025-12-11 15:30:45.949373 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-12-11 15:30:45.949399 | controller | }
2025-12-11 15:30:46.134204 | controller | changed:
2025-12-11 15:30:46.134255 | controller | {
2025-12-11 15:30:46.134279 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-12-11 15:30:46.134310 | controller | }
2025-12-11 15:30:46.317732 | controller | changed:
2025-12-11 15:30:46.317790 | controller | {
2025-12-11 15:30:46.317821 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2025-12-11 15:30:46.317847 | controller | }
2025-12-11 15:30:46.503975 | controller | changed:
2025-12-11 15:30:46.504023 | controller | {
2025-12-11 15:30:46.504049 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2025-12-11 15:30:46.504070 | controller | }
2025-12-11 15:30:46.688647 | controller | changed:
2025-12-11 15:30:46.688703 | controller | {
2025-12-11 15:30:46.688728 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-12-11 15:30:46.688748 | controller | }
2025-12-11 15:30:46.879204 | controller | changed:
2025-12-11 15:30:46.879450 | controller | {
2025-12-11 15:30:46.879492 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-12-11 15:30:46.879515 | controller | }
2025-12-11 15:30:47.068098 | controller | changed:
2025-12-11 15:30:47.068158 | controller | {
2025-12-11 15:30:47.068184 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-12-11 15:30:47.068205 | controller | }
2025-12-11 15:30:47.274268 | controller | changed:
2025-12-11 15:30:47.274370 | controller | {
2025-12-11 15:30:47.274396 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-12-11 15:30:47.274417 | controller | }
2025-12-11 15:30:47.443677 | controller | changed:
2025-12-11 15:30:47.443739 | controller | {
2025-12-11 15:30:47.443766 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-12-11 15:30:47.443787 | controller | }
2025-12-11 15:30:47.630874 | controller | changed:
2025-12-11 15:30:47.630941 | controller | {
2025-12-11 15:30:47.630967 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-12-11 15:30:47.630985 | controller | }
2025-12-11 15:30:47.817780 | controller | changed:
2025-12-11 15:30:47.817830 | controller | {
2025-12-11 15:30:47.817854 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-12-11 15:30:47.817874 | controller | }
2025-12-11 15:30:48.007983 | controller | changed:
2025-12-11 15:30:48.008185 | controller | {
2025-12-11 15:30:48.008226 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-12-11 15:30:48.008248 | controller | }
2025-12-11 15:30:48.194929 | controller | changed:
2025-12-11 15:30:48.194979 | controller | {
2025-12-11 15:30:48.195002 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2025-12-11 15:30:48.195023 | controller | }
2025-12-11 15:30:48.383770 | controller | changed:
2025-12-11 15:30:48.383821 | controller | {
2025-12-11 15:30:48.383847 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2025-12-11 15:30:48.383875 | controller | }
2025-12-11 15:30:48.572046 | controller | changed:
2025-12-11 15:30:48.572098 | controller | {
2025-12-11 15:30:48.572121 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-12-11 15:30:48.572139 | controller | }
2025-12-11 15:30:48.765119 | controller | changed:
2025-12-11 15:30:48.765173 | controller | {
2025-12-11 15:30:48.765200 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-12-11 15:30:48.765221 | controller | }
2025-12-11 15:30:48.951797 | controller | changed:
2025-12-11 15:30:48.951842 | controller | {
2025-12-11 15:30:48.951865 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-12-11 15:30:48.951883 | controller | }
2025-12-11 15:30:49.140244 | controller | changed:
2025-12-11 15:30:49.140302 | controller | {
2025-12-11 15:30:49.140327 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-12-11 15:30:49.140346 | controller | }
2025-12-11 15:30:49.329647 | controller | changed:
2025-12-11 15:30:49.329694 | controller | {
2025-12-11 15:30:49.329718 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2025-12-11 15:30:49.329738 | controller | }
2025-12-11 15:30:49.521094 | controller | changed:
2025-12-11 15:30:49.521140 | controller | {
2025-12-11 15:30:49.521164 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-12-11 15:30:49.521290 | controller | }
2025-12-11 15:30:49.709172 | controller | changed:
2025-12-11 15:30:49.709220 | controller | {
2025-12-11 15:30:49.709242 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-12-11 15:30:49.709261 | controller | }
2025-12-11 15:30:49.897273 | controller | changed:
2025-12-11 15:30:49.897331 | controller | {
2025-12-11 15:30:49.897354 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-12-11 15:30:49.897372 | controller | }
2025-12-11 15:30:49.920532 | 
2025-12-11 15:30:49.920744 | TASK [Set timezone to UTC]
2025-12-11 15:30:50.286969 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-12-11 15:30:50.292017 | 
2025-12-11 15:30:50.292096 | TASK [Create nodepool directory]
2025-12-11 15:30:50.489519 | controller | changed
2025-12-11 15:30:50.495169 | 
2025-12-11 15:30:50.495234 | TASK [Create nodepool sub_nodes file]
2025-12-11 15:30:50.974574 | controller | changed
2025-12-11 15:30:50.981064 | 
2025-12-11 15:30:50.981141 | TASK [Create nodepool sub_nodes_private file]
2025-12-11 15:30:51.445023 | controller | changed
2025-12-11 15:30:51.449858 | 
2025-12-11 15:30:51.449950 | LOOP [Populate nodepool sub_nodes file]
2025-12-11 15:30:51.490936 | 
2025-12-11 15:30:51.491071 | LOOP [Populate nodepool sub_nodes_private file]
2025-12-11 15:30:51.521348 | 
2025-12-11 15:30:51.521485 | TASK [Create nodepool primary file]
2025-12-11 15:30:51.545890 | controller | skipping: Conditional result was False
2025-12-11 15:30:51.551861 | 
2025-12-11 15:30:51.551958 | TASK [Create nodepool node_private for this node]
2025-12-11 15:30:52.067577 | controller | changed
2025-12-11 15:30:52.072957 | 
2025-12-11 15:30:52.073026 | LOOP [Copy ssh keys to nodepool directory]
2025-12-11 15:30:52.447926 | controller | ok: Item: id_rsa Runtime: 0:00:00.004700
2025-12-11 15:30:52.448108 | 
2025-12-11 15:30:52.594542 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.004088
2025-12-11 15:30:52.609541 | 
2025-12-11 15:30:52.609604 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-12-11 15:30:53.106298 | controller | changed
2025-12-11 15:30:53.111317 | 
2025-12-11 15:30:53.111384 | TASK [Validate sudoers config after edits]
2025-12-11 15:30:53.312948 | controller | /etc/sudoers: parsed OK
2025-12-11 15:30:53.313014 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-12-11 15:30:53.313024 | controller | /etc/sudoers.d/zuul: parsed OK
2025-12-11 15:30:53.313030 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-12-11 15:30:53.640217 | controller | ok: Runtime: 0:00:00.005515
2025-12-11 15:30:53.646314 | 
2025-12-11 15:30:53.646380 | TASK [Show the environment passed in to job shell scripts]
2025-12-11 15:30:53.827661 | controller | SHELL=/bin/bash
2025-12-11 15:30:53.827706 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-12-11 15:30:53.827715 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-12-11 15:30:53.827734 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/45/3545/d27cfeda72573fc3160d047cd4f472076517eaaa
2025-12-11 15:30:53.827780 | controller | PWD=/home/zuul
2025-12-11 15:30:53.827789 | controller | ZUUL_PIPELINE=github-check
2025-12-11 15:30:53.827795 | controller | LOGNAME=zuul
2025-12-11 15:30:53.827800 | controller | XDG_SESSION_TYPE=tty
2025-12-11 15:30:53.827806 | controller | _=/usr/bin/env
2025-12-11 15:30:53.827811 | controller | MOTD_SHOWN=pam
2025-12-11 15:30:53.827816 | controller | HOME=/home/zuul
2025-12-11 15:30:53.827821 | controller | LANG=en_US.UTF-8
2025-12-11 15:30:53.827827 | controller | SSH_CONNECTION=192.168.26.12 57570 192.168.26.235 22
2025-12-11 15:30:53.827832 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2025-12-11 15:30:53.827841 | controller | ZUUL_CHANGE_IDS=3545,d27cfeda72573fc3160d047cd4f472076517eaaa
2025-12-11 15:30:53.827846 | controller | WORKSPACE=/home/zuul/workspace
2025-12-11 15:30:53.827865 | controller | XDG_SESSION_CLASS=user
2025-12-11 15:30:53.827875 | controller | SELINUX_ROLE_REQUESTED=
2025-12-11 15:30:53.827880 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-12-11 15:30:53.827886 | controller | USER=zuul
2025-12-11 15:30:53.827891 | controller | ZUUL_VOTING=True
2025-12-11 15:30:53.827896 | controller | BUILD_TIMEOUT=1800000
2025-12-11 15:30:53.827902 | controller | SELINUX_USE_CURRENT_RANGE=
2025-12-11 15:30:53.827907 | controller | SHLVL=1
2025-12-11 15:30:53.827912 | controller | ZUUL_PATCHSET=d27cfeda72573fc3160d047cd4f472076517eaaa
2025-12-11 15:30:53.827917 | controller | XDG_SESSION_ID=1
2025-12-11 15:30:53.827923 | controller | ZUUL_BRANCH=main
2025-12-11 15:30:53.827928 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-12-11 15:30:53.827933 | controller | SSH_CLIENT=192.168.26.12 57570 22
2025-12-11 15:30:53.827939 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-12-11 15:30:53.827944 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-12-11 15:30:53.827949 | controller | which_declare=declare -f
2025-12-11 15:30:53.827955 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-12-11 15:30:53.827961 | controller | SELINUX_LEVEL_REQUESTED=
2025-12-11 15:30:53.827966 | controller | ZUUL_CHANGE=3545
2025-12-11 15:30:53.827972 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-12-11 15:30:53.827977 | controller | ZUUL_UUID=22aab5ab0d604d9fa8ec4fd2c4f9ac3b
2025-12-11 15:30:53.827982 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-12-11 15:30:53.827988 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-12-11 15:30:53.827993 | controller | }
2025-12-11 15:30:54.172034 | controller | ok: Runtime: 0:00:00.004906
2025-12-11 15:30:54.177136 | 
2025-12-11 15:30:54.177197 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-12-11 15:30:54.201209 | controller | skipping: Conditional result was False
2025-12-11 15:30:54.206846 | 
2025-12-11 15:30:54.206940 | TASK [Symlink /home/zuul-worker/workspace]
2025-12-11 15:30:54.733456 | controller | skipping: Conditional result was False
2025-12-11 15:30:54.739266 | 
2025-12-11 15:30:54.739350 | TASK [Ensure legacy workspace directory]
2025-12-11 15:30:54.930282 | controller | changed
2025-12-11 15:30:54.947594 | 
2025-12-11 15:30:54.947646 | PLAY RECAP
2025-12-11 15:30:54.947693 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-12-11 15:30:54.947715 | 
2025-12-11 15:30:55.025709 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-12-11 15:30:55.026823 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-12-11 15:30:55.504188 | 
2025-12-11 15:30:55.504363 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-12-11 15:30:55.523356 | 
2025-12-11 15:30:55.523437 | TASK [Create zuul-output directory]
2025-12-11 15:30:55.817453 | controller | changed
2025-12-11 15:30:55.822116 | 
2025-12-11 15:30:55.822191 | TASK [Slurp Zuul inventory test]
2025-12-11 15:30:56.089373 | controller -> localhost | ok
2025-12-11 15:30:56.095578 | 
2025-12-11 15:30:56.095648 | TASK [Save zuul inventory]
2025-12-11 15:30:56.772754 | controller | changed
2025-12-11 15:30:56.777873 | 
2025-12-11 15:30:56.777967 | TASK [Save zuul vars without the change_message]
2025-12-11 15:30:57.323201 | controller | changed
2025-12-11 15:30:57.341572 | 
2025-12-11 15:30:57.341630 | PLAY RECAP
2025-12-11 15:30:57.341679 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-11 15:30:57.341702 | 
2025-12-11 15:30:57.419771 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-12-11 15:30:57.420582 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-12-11 15:30:57.949090 | 
2025-12-11 15:30:57.949219 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-12-11 15:30:57.968411 | 
2025-12-11 15:30:57.968489 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-12-11 15:30:57.987835 | controller | ok
2025-12-11 15:30:58.004386 | 
2025-12-11 15:30:58.004470 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-12-11 15:30:58.028697 | controller | skipping: Conditional result was False
2025-12-11 15:30:58.034480 | 
2025-12-11 15:30:58.034554 | TASK [mirror-info-fork : Create /etc/ci]
2025-12-11 15:30:58.338727 | controller | ok
2025-12-11 15:30:58.344201 | 
2025-12-11 15:30:58.344284 | TASK [mirror-info-fork : Install ci_mirror script]
2025-12-11 15:30:58.923785 | controller | ok
2025-12-11 15:30:58.933551 | 
2025-12-11 15:30:58.933615 | TASK [Prepare workspace]
2025-12-11 15:30:58.951826 | controller | ok
2025-12-11 15:30:58.967311 | 
2025-12-11 15:30:58.967375 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-11 15:30:59.239322 | controller | ok
2025-12-11 15:30:59.244962 | 
2025-12-11 15:30:59.245026 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-11 15:31:01.538191 | controller | Output suppressed because no_log was given
2025-12-11 15:31:01.546795 | 
2025-12-11 15:31:01.546862 | LOOP [Create zuul-output directory]
2025-12-11 15:31:01.720216 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-12-11 15:31:01.861331 | controller | ok: "/home/zuul/zuul-output/logs"
2025-12-11 15:31:01.873411 | 
2025-12-11 15:31:01.873519 | TASK [Install required packages]
2025-12-11 15:31:48.283500 | controller | changed
2025-12-11 15:31:48.288680 | 
2025-12-11 15:31:48.288754 | TASK [Install venv]
2025-12-11 15:32:50.255372 | controller | changed
2025-12-11 15:32:50.278082 | 
2025-12-11 15:32:50.278155 | PLAY RECAP
2025-12-11 15:32:50.278220 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-12-11 15:32:50.278251 | 
2025-12-11 15:32:50.343771 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-12-11 15:32:50.344632 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-12-11 15:32:50.838288 | 
2025-12-11 15:32:50.838386 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-12-11 15:32:50.858360 | 
2025-12-11 15:32:50.858435 | TASK [Gather required facts]
2025-12-11 15:32:51.314350 | controller | ok
2025-12-11 15:32:51.319140 | 
2025-12-11 15:32:51.319218 | TASK [Load environment var if instructed to]
2025-12-11 15:32:51.342997 | controller | skipping: Conditional result was False
2025-12-11 15:32:51.348557 | 
2025-12-11 15:32:51.348627 | TASK [Ensure group_vars dir exists]
2025-12-11 15:32:51.642306 | controller | ok
2025-12-11 15:32:51.648081 | 
2025-12-11 15:32:51.648142 | TASK [Print related variables]
2025-12-11 15:32:51.676028 | controller | ok:
2025-12-11 15:32:51.676132 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2025-12-11 15:32:51.676162 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/nat64_appliance
2025-12-11 15:32:51.680629 | 
2025-12-11 15:32:51.680686 | TASK [Run molecule]
2025-12-11 15:32:52.540978 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-12-11 15:32:52.604818 | controller | INFO     Performing prerun with role_name_check=0...
2025-12-11 15:33:09.075178 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.075414 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.075431 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.075831 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.076283 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+4557c9a8 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+4557c9a8 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.076712 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.077130 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.077540 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.077965 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.078362 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.078817 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.079282 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.079735 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.080192 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.080623 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-12-11 15:33:09.089788 | controller | INFO     Running default > prepare
2025-12-11 15:33:09.739868 | controller |
2025-12-11 15:33:09.739996 | controller | PLAY [Prepare] *****************************************************************
2025-12-11 15:33:09.740109 | controller |
2025-12-11 15:33:09.740225 | controller | TASK [Gathering Facts] *********************************************************
2025-12-11 15:33:09.740328 | controller | Thursday 11 December 2025  15:33:09 +0000 (0:00:00.018)       0:00:00.018 *****
2025-12-11 15:33:10.547342 | controller | ok: [instance]
2025-12-11 15:33:10.547410 | controller |
2025-12-11 15:33:10.547521 | controller | TASK [Create custom basedir] ***************************************************
2025-12-11 15:33:10.547619 | controller | Thursday 11 December 2025  15:33:10 +0000 (0:00:00.808)       0:00:00.826 *****
2025-12-11 15:33:10.854579 | controller | ok: [instance]
2025-12-11 15:33:10.854664 | controller |
2025-12-11 15:33:10.854776 | controller | TASK [Install some debug utils] ************************************************
2025-12-11 15:33:10.854899 | controller | Thursday 11 December 2025  15:33:10 +0000 (0:00:00.307)       0:00:01.133 *****
2025-12-11 15:33:15.330591 | controller | changed: [instance]
2025-12-11 15:33:15.330644 | controller |
2025-12-11 15:33:15.330758 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-12-11 15:33:15.331755 | controller | Thursday 11 December 2025  15:33:15 +0000 (0:00:04.476)       0:00:05.609 *****
2025-12-11 15:33:15.352359 | controller | skipping: [instance]
2025-12-11 15:33:15.352472 | controller |
2025-12-11 15:33:15.352598 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-12-11 15:33:15.352724 | controller | Thursday 11 December 2025  15:33:15 +0000 (0:00:00.022)       0:00:05.631 *****
2025-12-11 15:33:15.392625 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-12-11 15:33:15.392728 | controller |
2025-12-11 15:33:15.392885 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-12-11 15:33:15.393023 | controller | Thursday 11 December 2025  15:33:15 +0000 (0:00:00.040)       0:00:05.671 *****
2025-12-11 15:33:15.679308 | controller | ok: [instance]
2025-12-11 15:33:15.679357 | controller |
2025-12-11 15:33:15.679431 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-12-11 15:33:15.679538 | controller | Thursday 11 December 2025  15:33:15 +0000 (0:00:00.286)       0:00:05.958 *****
2025-12-11 15:33:15.899955 | controller | ok: [instance]
2025-12-11 15:33:15.900020 | controller |
2025-12-11 15:33:15.900142 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-12-11 15:33:15.900254 | controller | Thursday 11 December 2025  15:33:15 +0000 (0:00:00.220)       0:00:06.179 *****
2025-12-11 15:33:16.577070 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-12-11 15:33:16.577576 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-12-11 15:33:16.634985 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-12-11 15:33:16.635026 | controller |
2025-12-11 15:33:16.635037 | controller | TASK [Deploy repo-setup] *******************************************************
2025-12-11 15:33:16.635046 | controller | Thursday 11 December 2025  15:33:16 +0000 (0:00:00.676)       0:00:06.855 *****
2025-12-11 15:33:16.635060 | controller |
2025-12-11 15:33:17.173962 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-12-11 15:33:17.174017 | controller | Thursday 11 December 2025  15:33:16 +0000 (0:00:00.058)       0:00:06.914 *****
2025-12-11 15:33:17.174033 | controller | changed: [instance] => (item=tmp)
2025-12-11 15:33:17.174495 | controller | changed: [instance] => (item=artifacts/repositories)
2025-12-11 15:33:17.822660 | controller | changed: [instance] => (item=venv/repo_setup)
2025-12-11 15:33:17.822699 | controller |
2025-12-11 15:33:17.822714 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-12-11 15:33:17.822720 | controller | Thursday 11 December 2025  15:33:17 +0000 (0:00:00.538)       0:00:07.453 *****
2025-12-11 15:33:17.822730 | controller | ok: [instance]
2025-12-11 15:33:18.882931 | controller |
2025-12-11 15:33:18.882967 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-12-11 15:33:18.882974 | controller | Thursday 11 December 2025  15:33:17 +0000 (0:00:00.648)       0:00:08.101 *****
2025-12-11 15:33:18.882984 | controller | changed: [instance]
2025-12-11 15:33:26.629764 | controller |
2025-12-11 15:33:26.629796 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-12-11 15:33:26.629803 | controller | Thursday 11 December 2025  15:33:18 +0000 (0:00:01.058)       0:00:09.159 *****
2025-12-11 15:33:26.629813 | controller | changed: [instance]
2025-12-11 15:33:27.311738 | controller |
2025-12-11 15:33:27.311767 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-12-11 15:33:27.311775 | controller | Thursday 11 December 2025  15:33:26 +0000 (0:00:07.748)       0:00:16.908 *****
2025-12-11 15:33:27.311784 | controller | changed: [instance]
2025-12-11 15:33:27.332918 | controller |
2025-12-11 15:33:27.332944 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-12-11 15:33:27.332951 | controller | Thursday 11 December 2025  15:33:27 +0000 (0:00:00.681)       0:00:17.590 *****
2025-12-11 15:33:27.332960 | controller | skipping: [instance]
2025-12-11 15:33:28.116685 | controller |
2025-12-11 15:33:28.116713 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-12-11 15:33:28.116721 | controller | Thursday 11 December 2025  15:33:27 +0000 (0:00:00.021)       0:00:17.612 *****
2025-12-11 15:33:28.116731 | controller | changed: [instance]
2025-12-11 15:33:28.151258 | controller |
2025-12-11 15:33:28.151279 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-12-11 15:33:28.151288 | controller | Thursday 11 December 2025  15:33:28 +0000 (0:00:00.783)       0:00:18.395 *****
2025-12-11 15:33:28.151298 | controller | skipping: [instance]
2025-12-11 15:33:28.185772 | controller |
2025-12-11 15:33:28.185790 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-12-11 15:33:28.185798 | controller | Thursday 11 December 2025  15:33:28 +0000 (0:00:00.034)       0:00:18.430 *****
2025-12-11 15:33:28.185807 | controller | skipping: [instance]
2025-12-11 15:33:28.234724 | controller |
2025-12-11 15:33:28.234740 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-12-11 15:33:28.234746 | controller | Thursday 11 December 2025  15:33:28 +0000 (0:00:00.034)       0:00:18.464 *****
2025-12-11 15:33:28.234754 | controller | skipping: [instance]
2025-12-11 15:33:28.783139 | controller |
2025-12-11 15:33:28.783169 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-12-11 15:33:28.783178 | controller | Thursday 11 December 2025  15:33:28 +0000 (0:00:00.049)       0:00:18.513 *****
2025-12-11 15:33:28.783188 | controller | changed: [instance]
2025-12-11 15:33:29.198394 | controller |
2025-12-11 15:33:29.198423 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-12-11 15:33:29.198430 | controller | Thursday 11 December 2025  15:33:28 +0000 (0:00:00.547)       0:00:19.061 *****
2025-12-11 15:33:29.198443 | controller | changed: [instance]
2025-12-11 15:33:29.226427 | controller |
2025-12-11 15:33:29.226445 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-12-11 15:33:29.226452 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.415)       0:00:19.477 *****
2025-12-11 15:33:29.226461 | controller | skipping: [instance]
2025-12-11 15:33:29.254483 | controller |
2025-12-11 15:33:29.254499 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-12-11 15:33:29.254505 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.028)       0:00:19.505 *****
2025-12-11 15:33:29.254513 | controller | skipping: [instance]
2025-12-11 15:33:29.281347 | controller |
2025-12-11 15:33:29.281365 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-12-11 15:33:29.281372 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.028)       0:00:19.533 *****
2025-12-11 15:33:29.281380 | controller | skipping: [instance]
2025-12-11 15:33:29.317924 | controller |
2025-12-11 15:33:29.317943 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-12-11 15:33:29.317950 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.026)       0:00:19.560 *****
2025-12-11 15:33:29.317966 | controller | ok: [instance]
2025-12-11 15:33:29.343356 | controller |
2025-12-11 15:33:29.343374 | controller | TASK [repo_setup : Create download directory] **********************************
2025-12-11 15:33:29.343383 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.036)       0:00:19.596 *****
2025-12-11 15:33:29.343393 | controller | skipping: [instance]
2025-12-11 15:33:29.367345 | controller |
2025-12-11 15:33:29.367386 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-12-11 15:33:29.367396 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.025)       0:00:19.622 *****
2025-12-11 15:33:29.367408 | controller | skipping: [instance]
2025-12-11 15:33:29.391810 | controller |
2025-12-11 15:33:29.391840 | controller | TASK [Download the RPM] ********************************************************
2025-12-11 15:33:29.391875 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.023)       0:00:19.646 *****
2025-12-11 15:33:29.391887 | controller | skipping: [instance]
2025-12-11 15:33:29.418868 | controller |
2025-12-11 15:33:29.418893 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-12-11 15:33:29.418901 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.024)       0:00:19.670 *****
2025-12-11 15:33:29.418910 | controller | skipping: [instance]
2025-12-11 15:33:29.445805 | controller |
2025-12-11 15:33:29.445822 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-12-11 15:33:29.445830 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.027)       0:00:19.697 *****
2025-12-11 15:33:29.445839 | controller | skipping: [instance]
2025-12-11 15:33:29.472802 | controller |
2025-12-11 15:33:29.472819 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-12-11 15:33:29.472825 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.027)       0:00:19.724 *****
2025-12-11 15:33:29.472834 | controller | skipping: [instance]
2025-12-11 15:33:29.497917 | controller |
2025-12-11 15:33:29.497938 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-12-11 15:33:29.497947 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.027)       0:00:19.752 *****
2025-12-11 15:33:29.497958 | controller | skipping: [instance]
2025-12-11 15:33:29.498156 | controller |
2025-12-11 15:33:29.498176 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-12-11 15:33:29.676657 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.025)       0:00:19.777 *****
2025-12-11 15:33:29.676694 | controller | ok: [instance]
2025-12-11 15:33:29.878922 | controller |
2025-12-11 15:33:29.878950 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-12-11 15:33:29.878958 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.178)       0:00:19.955 *****
2025-12-11 15:33:29.878967 | controller | changed: [instance]
2025-12-11 15:33:29.878991 | controller |
2025-12-11 15:33:29.879002 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-12-11 15:33:29.879124 | controller | Thursday 11 December 2025  15:33:29 +0000 (0:00:00.202)       0:00:20.157 *****
2025-12-11 15:33:30.102667 | controller | changed: [instance]
2025-12-11 15:33:30.122534 | controller |
2025-12-11 15:33:30.122559 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-12-11 15:33:30.122566 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.223)       0:00:20.381 *****
2025-12-11 15:33:30.122575 | controller | skipping: [instance]
2025-12-11 15:33:30.146936 | controller |
2025-12-11 15:33:30.146970 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-12-11 15:33:30.146979 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.020)       0:00:20.401 *****
2025-12-11 15:33:30.146990 | controller | skipping: [instance]
2025-12-11 15:33:30.169403 | controller |
2025-12-11 15:33:30.169427 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-12-11 15:33:30.169435 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.024)       0:00:20.426 *****
2025-12-11 15:33:30.169445 | controller | skipping: [instance]
2025-12-11 15:33:30.191850 | controller |
2025-12-11 15:33:30.191889 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-12-11 15:33:30.191906 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.022)       0:00:20.448 *****
2025-12-11 15:33:30.191917 | controller | skipping: [instance]
2025-12-11 15:33:30.214809 | controller |
2025-12-11 15:33:30.214827 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-12-11 15:33:30.214835 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.022)       0:00:20.470 *****
2025-12-11 15:33:30.214845 | controller | skipping: [instance]
2025-12-11 15:33:30.236465 | controller |
2025-12-11 15:33:30.236481 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-12-11 15:33:30.236488 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.022)       0:00:20.493 *****
2025-12-11 15:33:30.236496 | controller | skipping: [instance]
2025-12-11 15:33:30.252371 | controller |
2025-12-11 15:33:30.252389 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-12-11 15:33:30.252397 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.021)       0:00:20.515 *****
2025-12-11 15:33:30.252406 | controller | skipping: [instance]
2025-12-11 15:33:30.281382 | controller |
2025-12-11 15:33:30.281403 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-12-11 15:33:30.281411 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.015)       0:00:20.531 *****
2025-12-11 15:33:30.281422 | controller | skipping: [instance]
2025-12-11 15:33:30.297435 | controller |
2025-12-11 15:33:30.297452 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-12-11 15:33:30.297459 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.028)       0:00:20.560 *****
2025-12-11 15:33:30.297469 | controller | skipping: [instance]
2025-12-11 15:33:30.316235 | controller |
2025-12-11 15:33:30.316250 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-12-11 15:33:30.316256 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.016)       0:00:20.576 *****
2025-12-11 15:33:30.316263 | controller | skipping: [instance]
2025-12-11 15:33:30.344278 | controller |
2025-12-11 15:33:30.344295 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-12-11 15:33:30.344302 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.018)       0:00:20.595 *****
2025-12-11 15:33:30.344309 | controller | skipping: [instance]
2025-12-11 15:33:30.373128 | controller |
2025-12-11 15:33:30.373148 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-12-11 15:33:30.373157 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.027)       0:00:20.623 *****
2025-12-11 15:33:30.373167 | controller | skipping: [instance]
2025-12-11 15:33:30.404915 | controller |
2025-12-11 15:33:30.404933 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-12-11 15:33:30.404940 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.028)       0:00:20.652 *****
2025-12-11 15:33:30.404948 | controller | skipping: [instance]
2025-12-11 15:33:30.405014 | controller |
2025-12-11 15:33:30.405026 | controller | TASK [test_deps : Install additional packages] *********************************
2025-12-11 15:33:30.405116 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.032)       0:00:20.684 *****
2025-12-11 15:33:30.434345 | controller | skipping: [instance]
2025-12-11 15:33:30.434435 | controller |
2025-12-11 15:33:30.434534 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-12-11 15:33:30.434630 | controller | Thursday 11 December 2025  15:33:30 +0000 (0:00:00.029)       0:00:20.713 *****
2025-12-11 15:34:12.248663 | controller | ok: [instance]
2025-12-11 15:34:12.248722 | controller |
2025-12-11 15:34:12.248995 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-12-11 15:34:13.369787 | controller | Thursday 11 December 2025  15:34:12 +0000 (0:00:41.813)       0:01:02.527 *****
2025-12-11 15:34:13.369831 | controller | ok: [instance]
2025-12-11 15:34:13.369865 | controller |
2025-12-11 15:34:13.370116 | controller | TASK [test_deps : Install extra packages] **************************************
2025-12-11 15:34:13.409413 | controller | Thursday 11 December 2025  15:34:13 +0000 (0:00:01.121)       0:01:03.648 *****
2025-12-11 15:34:13.409436 | controller | skipping: [instance]
2025-12-11 15:34:13.606930 | controller |
2025-12-11 15:34:13.606961 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-12-11 15:34:13.606969 | controller | Thursday 11 December 2025  15:34:13 +0000 (0:00:00.039)       0:01:03.688 *****
2025-12-11 15:34:13.606985 | controller | ok: [instance]
2025-12-11 15:34:13.790390 | controller |
2025-12-11 15:34:13.790420 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-12-11 15:34:13.790427 | controller | Thursday 11 December 2025  15:34:13 +0000 (0:00:00.197)       0:01:03.885 *****
2025-12-11 15:34:13.790437 | controller | changed: [instance]
2025-12-11 15:34:13.976777 | controller |
2025-12-11 15:34:13.976807 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-12-11 15:34:13.976815 | controller | Thursday 11 December 2025  15:34:13 +0000 (0:00:00.183)       0:01:04.069 *****
2025-12-11 15:34:13.976825 | controller | ok: [instance]
2025-12-11 15:34:14.004735 | controller |
2025-12-11 15:34:14.004757 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-12-11 15:34:14.004767 | controller | Thursday 11 December 2025  15:34:13 +0000 (0:00:00.186)       0:01:04.255 *****
2025-12-11 15:34:14.004778 | controller | skipping: [instance]
2025-12-11 15:34:14.020975 | controller |
2025-12-11 15:34:14.021021 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-12-11 15:34:14.021031 | controller | Thursday 11 December 2025  15:34:14 +0000 (0:00:00.028)       0:01:04.283 *****
2025-12-11 15:34:14.021044 | controller | skipping: [instance]
2025-12-11 15:34:14.021076 | controller |
2025-12-11 15:34:14.021086 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-12-11 15:34:14.041508 | controller | Thursday 11 December 2025  15:34:14 +0000 (0:00:00.016)       0:01:04.300 *****
2025-12-11 15:34:14.041533 | controller | ok: [instance]
2025-12-11 15:34:14.066402 | controller |
2025-12-11 15:34:14.066420 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-12-11 15:34:14.066428 | controller | Thursday 11 December 2025  15:34:14 +0000 (0:00:00.020)       0:01:04.320 *****
2025-12-11 15:34:14.066437 | controller | skipping: [instance]
2025-12-11 15:35:20.935264 | controller |
2025-12-11 15:35:20.935306 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-12-11 15:35:20.935315 | controller | Thursday 11 December 2025  15:34:14 +0000 (0:00:00.025)       0:01:04.345 *****
2025-12-11 15:35:20.935326 | controller | changed: [instance]
2025-12-11 15:35:20.935352 | controller |
2025-12-11 15:35:20.935359 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-12-11 15:35:20.935367 | controller | Thursday 11 December 2025  15:35:20 +0000 (0:01:06.868)       0:02:11.214 *****
2025-12-11 15:35:21.168842 | controller | changed: [instance]
2025-12-11 15:35:21.577515 | controller |
2025-12-11 15:35:21.577547 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-12-11 15:35:21.577555 | controller | Thursday 11 December 2025  15:35:21 +0000 (0:00:00.233)       0:02:11.447 *****
2025-12-11 15:35:21.577565 | controller | changed: [instance]
2025-12-11 15:35:22.215429 | controller |
2025-12-11 15:35:22.215458 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-12-11 15:35:22.215465 | controller | Thursday 11 December 2025  15:35:21 +0000 (0:00:00.408)       0:02:11.855 *****
2025-12-11 15:35:22.215475 | controller | changed: [instance]
2025-12-11 15:35:22.426364 | controller |
2025-12-11 15:35:22.426394 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-12-11 15:35:22.426403 | controller | Thursday 11 December 2025  15:35:22 +0000 (0:00:00.638)       0:02:12.494 *****
2025-12-11 15:35:22.426413 | controller | ok: [instance]
2025-12-11 15:35:23.203165 | controller |
2025-12-11 15:35:23.203199 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-12-11 15:35:23.203208 | controller | Thursday 11 December 2025  15:35:22 +0000 (0:00:00.210)       0:02:12.704 *****
2025-12-11 15:35:23.203218 | controller | ok: [instance]
2025-12-11 15:35:24.108928 | controller |
2025-12-11 15:35:24.108959 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-12-11 15:35:24.108966 | controller | Thursday 11 December 2025  15:35:23 +0000 (0:00:00.776)       0:02:13.481 *****
2025-12-11 15:35:24.108985 | controller | changed: [instance]
2025-12-11 15:35:24.109305 | controller |
2025-12-11 15:35:24.182291 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-12-11 15:35:24.182309 | controller | Thursday 11 December 2025  15:35:24 +0000 (0:00:00.906)       0:02:14.387 *****
2025-12-11 15:35:24.182319 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-12-11 15:35:24.537546 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-12-11 15:35:24.537575 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-12-11 15:35:24.537582 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-12-11 15:35:24.537588 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-12-11 15:35:24.537594 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-12-11 15:35:24.537599 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-12-11 15:35:24.537604 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-12-11 15:35:24.537609 | controller |
2025-12-11 15:35:24.537624 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-12-11 15:35:24.537630 | controller | Thursday 11 December 2025  15:35:24 +0000 (0:00:00.072)       0:02:14.460 *****
2025-12-11 15:35:24.537638 | controller | changed: [instance]
2025-12-11 15:35:24.891960 | controller |
2025-12-11 15:35:24.892000 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-12-11 15:35:24.892016 | controller | Thursday 11 December 2025  15:35:24 +0000 (0:00:00.355)       0:02:14.816 *****
2025-12-11 15:35:24.892027 | controller | changed: [instance]
2025-12-11 15:35:24.892047 | controller |
2025-12-11 15:35:24.892106 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-12-11 15:35:24.892233 | controller | Thursday 11 December 2025  15:35:24 +0000 (0:00:00.354)       0:02:15.170 *****
2025-12-11 15:35:25.263027 | controller | changed: [instance]
2025-12-11 15:35:25.645881 | controller |
2025-12-11 15:35:25.645912 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-12-11 15:35:25.645928 | controller | Thursday 11 December 2025  15:35:25 +0000 (0:00:00.371)       0:02:15.541 *****
2025-12-11 15:35:25.645938 | controller | changed: [instance]
2025-12-11 15:35:26.008303 | controller |
2025-12-11 15:35:26.008333 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-12-11 15:35:26.008341 | controller | Thursday 11 December 2025  15:35:25 +0000 (0:00:00.382)       0:02:15.924 *****
2025-12-11 15:35:26.008350 | controller | changed: [instance]
2025-12-11 15:35:26.345105 | controller |
2025-12-11 15:35:26.345139 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-12-11 15:35:26.345147 | controller | Thursday 11 December 2025  15:35:26 +0000 (0:00:00.362)       0:02:16.286 *****
2025-12-11 15:35:26.345157 | controller | changed: [instance]
2025-12-11 15:35:26.687958 | controller |
2025-12-11 15:35:26.687988 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-12-11 15:35:26.687996 | controller | Thursday 11 December 2025  15:35:26 +0000 (0:00:00.336)       0:02:16.623 *****
2025-12-11 15:35:26.688005 | controller | changed: [instance]
2025-12-11 15:35:27.062554 | controller |
2025-12-11 15:35:27.062586 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-12-11 15:35:27.062594 | controller | Thursday 11 December 2025  15:35:26 +0000 (0:00:00.343)       0:02:16.966 *****
2025-12-11 15:35:27.062604 | controller | changed: [instance]
2025-12-11 15:35:27.427328 | controller |
2025-12-11 15:35:27.427366 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-12-11 15:35:27.427374 | controller | Thursday 11 December 2025  15:35:27 +0000 (0:00:00.374)       0:02:17.341 *****
2025-12-11 15:35:27.427384 | controller | changed: [instance]
2025-12-11 15:35:27.787465 | controller |
2025-12-11 15:35:27.787495 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-12-11 15:35:27.787502 | controller | Thursday 11 December 2025  15:35:27 +0000 (0:00:00.364)       0:02:17.705 *****
2025-12-11 15:35:27.787512 | controller | changed: [instance]
2025-12-11 15:35:28.148164 | controller |
2025-12-11 15:35:28.148198 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-12-11 15:35:28.148206 | controller | Thursday 11 December 2025  15:35:27 +0000 (0:00:00.360)       0:02:18.066 *****
2025-12-11 15:35:28.148216 | controller | changed: [instance]
2025-12-11 15:35:28.531837 | controller |
2025-12-11 15:35:28.531886 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-12-11 15:35:28.531895 | controller | Thursday 11 December 2025  15:35:28 +0000 (0:00:00.360)       0:02:18.426 *****
2025-12-11 15:35:28.531905 | controller | changed: [instance]
2025-12-11 15:35:28.907844 | controller |
2025-12-11 15:35:28.907892 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-12-11 15:35:28.907901 | controller | Thursday 11 December 2025  15:35:28 +0000 (0:00:00.383)       0:02:18.810 *****
2025-12-11 15:35:28.907911 | controller | changed: [instance]
2025-12-11 15:35:29.248335 | controller |
2025-12-11 15:35:29.248361 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-12-11 15:35:29.248370 | controller | Thursday 11 December 2025  15:35:28 +0000 (0:00:00.375)       0:02:19.186 *****
2025-12-11 15:35:29.248380 | controller | changed: [instance]
2025-12-11 15:35:29.599958 | controller |
2025-12-11 15:35:29.599994 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-12-11 15:35:29.600002 | controller | Thursday 11 December 2025  15:35:29 +0000 (0:00:00.340)       0:02:19.527 *****
2025-12-11 15:35:29.600012 | controller | changed: [instance]
2025-12-11 15:35:29.600037 | controller |
2025-12-11 15:35:29.600045 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-12-11 15:35:29.600198 | controller | Thursday 11 December 2025  15:35:29 +0000 (0:00:00.351)       0:02:19.879 *****
2025-12-11 15:35:29.936782 | controller | changed: [instance]
2025-12-11 15:35:30.260233 | controller |
2025-12-11 15:35:30.260264 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-12-11 15:35:30.260272 | controller | Thursday 11 December 2025  15:35:29 +0000 (0:00:00.336)       0:02:20.215 *****
2025-12-11 15:35:30.260287 | controller | changed: [instance]
2025-12-11 15:35:30.601225 | controller |
2025-12-11 15:35:30.601258 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-12-11 15:35:30.601266 | controller | Thursday 11 December 2025  15:35:30 +0000 (0:00:00.323)       0:02:20.539 *****
2025-12-11 15:35:30.601277 | controller | changed: [instance]
2025-12-11 15:35:30.922352 | controller |
2025-12-11 15:35:30.922382 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-12-11 15:35:30.922391 | controller | Thursday 11 December 2025  15:35:30 +0000 (0:00:00.341)       0:02:20.880 *****
2025-12-11 15:35:30.922401 | controller | changed: [instance]
2025-12-11 15:35:31.243719 | controller |
2025-12-11 15:35:31.243750 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-12-11 15:35:31.243758 | controller | Thursday 11 December 2025  15:35:30 +0000 (0:00:00.321)       0:02:21.201 *****
2025-12-11 15:35:31.243768 | controller | changed: [instance]
2025-12-11 15:35:31.574121 | controller |
2025-12-11 15:35:31.574152 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-12-11 15:35:31.574159 | controller | Thursday 11 December 2025  15:35:31 +0000 (0:00:00.321)       0:02:21.522 *****
2025-12-11 15:35:31.574168 | controller | changed: [instance]
2025-12-11 15:35:31.927310 | controller |
2025-12-11 15:35:31.927339 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-12-11 15:35:31.927347 | controller | Thursday 11 December 2025  15:35:31 +0000 (0:00:00.330)       0:02:21.852 *****
2025-12-11 15:35:31.927364 | controller | changed: [instance]
2025-12-11 15:35:32.263617 | controller |
2025-12-11 15:35:32.263648 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-12-11 15:35:32.263656 | controller | Thursday 11 December 2025  15:35:31 +0000 (0:00:00.353)       0:02:22.206 *****
2025-12-11 15:35:32.263666 | controller | changed: [instance]
2025-12-11 15:35:32.615838 | controller |
2025-12-11 15:35:32.615886 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-12-11 15:35:32.615895 | controller | Thursday 11 December 2025  15:35:32 +0000 (0:00:00.336)       0:02:22.542 *****
2025-12-11 15:35:32.615905 | controller | changed: [instance]
2025-12-11 15:35:32.635548 | controller |
2025-12-11 15:35:32.635571 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-12-11 15:35:32.635579 | controller | Thursday 11 December 2025  15:35:32 +0000 (0:00:00.352)       0:02:22.894 *****
2025-12-11 15:35:32.635588 | controller | skipping: [instance]
2025-12-11 15:35:32.915935 | controller |
2025-12-11 15:35:32.915968 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-12-11 15:35:32.915977 | controller | Thursday 11 December 2025  15:35:32 +0000 (0:00:00.019)       0:02:22.914 *****
2025-12-11 15:35:32.915988 | controller | ok: [instance]
2025-12-11 15:35:33.342912 | controller |
2025-12-11 15:35:33.342944 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-12-11 15:35:33.342952 | controller | Thursday 11 December 2025  15:35:32 +0000 (0:00:00.279)       0:02:23.194 *****
2025-12-11 15:35:33.342962 | controller | changed: [instance]
2025-12-11 15:35:33.659129 | controller |
2025-12-11 15:35:33.659160 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-12-11 15:35:33.659168 | controller | Thursday 11 December 2025  15:35:33 +0000 (0:00:00.426)       0:02:23.621 *****
2025-12-11 15:35:33.659178 | controller | changed: [instance]
2025-12-11 15:35:33.941995 | controller |
2025-12-11 15:35:33.942035 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-12-11 15:35:33.942043 | controller | Thursday 11 December 2025  15:35:33 +0000 (0:00:00.316)       0:02:23.937 *****
2025-12-11 15:35:33.942052 | controller | [WARNING]: Reset is not implemented for this connection
2025-12-11 15:35:33.964057 | controller | changed: [instance]
2025-12-11 15:35:33.964146 | controller |
2025-12-11 15:35:33.964158 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-12-11 15:35:33.964167 | controller | Thursday 11 December 2025  15:35:33 +0000 (0:00:00.278)       0:02:24.216 *****
2025-12-11 15:35:33.964175 | controller |
2025-12-11 15:35:33.964183 | controller | PLAY RECAP *********************************************************************
2025-12-11 15:35:33.964190 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-12-11 15:35:33.964198 | controller |
2025-12-11 15:35:33.964204 | controller | Thursday 11 December 2025  15:35:33 +0000 (0:00:00.024)       0:02:24.241 *****
2025-12-11 15:35:33.964211 | controller | ===============================================================================
2025-12-11 15:35:33.964219 | controller | libvirt_manager : Install packages required for using KVM -------------- 66.87s
2025-12-11 15:35:33.964226 | controller | test_deps : Install selinux python libs -------------------------------- 41.81s
2025-12-11 15:35:33.964233 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.75s
2025-12-11 15:35:33.964248 | controller | Install some debug utils ------------------------------------------------ 4.48s
2025-12-11 15:35:33.964255 | controller | test_deps : Install python yaml libs ------------------------------------ 1.12s
2025-12-11 15:35:33.964262 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.06s
2025-12-11 15:35:33.964269 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.91s
2025-12-11 15:35:33.964275 | controller | Gathering Facts --------------------------------------------------------- 0.81s
2025-12-11 15:35:33.964282 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.78s
2025-12-11 15:35:33.964289 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.78s
2025-12-11 15:35:33.964296 | controller | repo_setup : Install repo-setup package --------------------------------- 0.68s
2025-12-11 15:35:33.964310 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.68s
2025-12-11 15:35:33.964340 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.65s
2025-12-11 15:35:33.964350 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.64s
2025-12-11 15:35:33.964433 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.55s
2025-12-11 15:35:33.964447 | controller | repo_setup : Ensure directories are present ----------------------------- 0.54s
2025-12-11 15:35:33.964556 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.43s
2025-12-11 15:35:33.964677 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.42s
2025-12-11 15:35:33.964809 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.41s
2025-12-11 15:35:33.964948 | controller | libvirt_manager : Ensure admin socket is enabled for nodedev. ----------- 0.38s
2025-12-11 15:35:34.031127 | controller | INFO     Running default > converge
2025-12-11 15:35:34.440358 | controller |
2025-12-11 15:35:35.289019 | controller | PLAY [Converge] ****************************************************************
2025-12-11 15:35:35.289076 | controller |
2025-12-11 15:35:35.289085 | controller | TASK [Gathering Facts] *********************************************************
2025-12-11 15:35:35.289092 | controller | Thursday 11 December 2025  15:35:34 +0000 (0:00:00.012)       0:00:00.012 *****
2025-12-11 15:35:35.289106 | controller | ok: [instance]
2025-12-11 15:35:35.289114 | controller |
2025-12-11 15:35:35.289124 | controller | TASK [Crate SSH keypair] *******************************************************
2025-12-11 15:35:35.668821 | controller | Thursday 11 December 2025  15:35:35 +0000 (0:00:00.848)       0:00:00.861 *****
2025-12-11 15:35:35.668895 | controller | changed: [instance]
2025-12-11 15:35:36.183943 | controller |
2025-12-11 15:35:36.183985 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-12-11 15:35:36.183994 | controller | Thursday 11 December 2025  15:35:35 +0000 (0:00:00.379)       0:00:01.240 *****
2025-12-11 15:35:36.184005 | controller | changed: [instance]
2025-12-11 15:35:37.210052 | controller |
2025-12-11 15:35:37.210085 | controller | TASK [Restart firewalld.service] ***********************************************
2025-12-11 15:35:37.210093 | controller | Thursday 11 December 2025  15:35:36 +0000 (0:00:00.514)       0:00:01.755 *****
2025-12-11 15:35:37.210103 | controller | changed: [instance]
2025-12-11 15:35:37.210345 | controller |
2025-12-11 15:35:37.210359 | controller | TASK [Discover latest image] ***************************************************
2025-12-11 15:35:37.250014 | controller | Thursday 11 December 2025  15:35:37 +0000 (0:00:01.026)       0:00:02.782 *****
2025-12-11 15:35:37.250067 | controller |
2025-12-11 15:35:38.845486 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-12-11 15:35:38.845523 | controller | Thursday 11 December 2025  15:35:37 +0000 (0:00:00.040)       0:00:02.822 *****
2025-12-11 15:35:38.845543 | controller | changed: [instance]
2025-12-11 15:35:38.874047 | controller |
2025-12-11 15:35:38.874119 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-12-11 15:35:38.874132 | controller | Thursday 11 December 2025  15:35:38 +0000 (0:00:01.595)       0:00:04.417 *****
2025-12-11 15:35:38.874148 | controller | ok: [instance]
2025-12-11 15:35:38.874188 | controller |
2025-12-11 15:35:38.874535 | controller | TASK [Download latest image] ***************************************************
2025-12-11 15:35:58.588080 | controller | Thursday 11 December 2025  15:35:38 +0000 (0:00:00.028)       0:00:04.446 *****
2025-12-11 15:35:58.588130 | controller | changed: [instance]
2025-12-11 15:35:58.626287 | controller |
2025-12-11 15:35:58.626308 | controller | TASK [Build nat64 appliance image] *********************************************
2025-12-11 15:35:58.626315 | controller | Thursday 11 December 2025  15:35:58 +0000 (0:00:19.712)       0:00:24.158 *****
2025-12-11 15:35:58.626324 | controller |
2025-12-11 15:35:59.084500 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-12-11 15:35:59.084527 | controller | Thursday 11 December 2025  15:35:58 +0000 (0:00:00.039)       0:00:24.198 *****
2025-12-11 15:35:59.084545 | controller | ok: [instance] => (item=artifacts)
2025-12-11 15:35:59.272442 | controller | ok: [instance] => (item=logs)
2025-12-11 15:35:59.272482 | controller |
2025-12-11 15:35:59.272490 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-12-11 15:35:59.272497 | controller | Thursday 11 December 2025  15:35:59 +0000 (0:00:00.457)       0:00:24.656 *****
2025-12-11 15:35:59.272508 | controller | changed: [instance]
2025-12-11 15:36:03.520324 | controller |
2025-12-11 15:36:03.520364 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-12-11 15:36:03.520371 | controller | Thursday 11 December 2025  15:35:59 +0000 (0:00:00.187)       0:00:24.844 *****
2025-12-11 15:36:03.520382 | controller | ok: [instance]
2025-12-11 15:36:11.219967 | controller |
2025-12-11 15:36:11.220003 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-12-11 15:36:11.220012 | controller | Thursday 11 December 2025  15:36:03 +0000 (0:00:04.247)       0:00:29.092 *****
2025-12-11 15:36:11.220022 | controller | changed: [instance]
2025-12-11 15:36:20.739962 | controller |
2025-12-11 15:36:20.740000 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-12-11 15:36:20.740008 | controller | Thursday 11 December 2025  15:36:11 +0000 (0:00:07.699)       0:00:36.791 *****
2025-12-11 15:36:20.740018 | controller | changed: [instance] => (item=elements/)
2025-12-11 15:36:20.740042 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-12-11 15:36:20.740049 | controller |
2025-12-11 15:36:20.740255 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-12-11 15:36:21.752631 | controller | Thursday 11 December 2025  15:36:20 +0000 (0:00:09.519)       0:00:46.311 *****
2025-12-11 15:36:21.752664 | controller | changed: [instance]
2025-12-11 15:40:25.397969 | controller |
2025-12-11 15:40:25.398301 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-12-11 15:40:25.398314 | controller | Thursday 11 December 2025  15:36:21 +0000 (0:00:01.013)       0:00:47.324 *****
2025-12-11 15:40:25.398327 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-12-11 15:40:25.430028 | controller | changed: [instance]
2025-12-11 15:40:25.430077 | controller |
2025-12-11 15:40:25.430086 | controller | TASK [nat64_appliance : Download pre-built NAT64 appliance image] **************
2025-12-11 15:40:25.430094 | controller | Thursday 11 December 2025  15:40:25 +0000 (0:04:03.645)       0:04:50.970 *****
2025-12-11 15:40:25.430107 | controller | skipping: [instance]
2025-12-11 15:40:25.656620 | controller |
2025-12-11 15:40:25.656655 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-12-11 15:40:25.656663 | controller | Thursday 11 December 2025  15:40:25 +0000 (0:00:00.032)       0:04:51.002 *****
2025-12-11 15:40:25.656673 | controller | changed: [instance]
2025-12-11 15:40:32.854445 | controller |
2025-12-11 15:40:32.854485 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-12-11 15:40:32.854493 | controller | Thursday 11 December 2025  15:40:25 +0000 (0:00:00.226)       0:04:51.228 *****
2025-12-11 15:40:32.854503 | controller | changed: [instance]
2025-12-11 15:40:32.912565 | controller |
2025-12-11 15:40:32.912593 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-12-11 15:40:32.912602 | controller | Thursday 11 December 2025  15:40:32 +0000 (0:00:07.195)       0:04:58.424 *****
2025-12-11 15:40:32.912612 | controller |
2025-12-11 15:40:32.971470 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-12-11 15:40:32.971495 | controller | Thursday 11 December 2025  15:40:32 +0000 (0:00:00.059)       0:04:58.484 *****
2025-12-11 15:40:32.971507 | controller | ok: [instance]
2025-12-11 15:40:33.829592 | controller |
2025-12-11 15:40:33.829626 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-12-11 15:40:33.829641 | controller | Thursday 11 December 2025  15:40:32 +0000 (0:00:00.059)       0:04:58.543 *****
2025-12-11 15:40:33.829651 | controller | changed: [instance]
2025-12-11 15:40:34.200995 | controller |
2025-12-11 15:40:34.201037 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-12-11 15:40:34.201049 | controller | Thursday 11 December 2025  15:40:33 +0000 (0:00:00.857)       0:04:59.401 *****
2025-12-11 15:40:34.201072 | controller | ok: [instance]
2025-12-11 15:40:34.430642 | controller |
2025-12-11 15:40:34.430677 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-12-11 15:40:34.430686 | controller | Thursday 11 December 2025  15:40:34 +0000 (0:00:00.371)       0:04:59.772 *****
2025-12-11 15:40:34.430696 | controller | ok: [instance]
2025-12-11 15:40:34.660624 | controller |
2025-12-11 15:40:34.660660 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-12-11 15:40:34.660668 | controller | Thursday 11 December 2025  15:40:34 +0000 (0:00:00.229)       0:05:00.002 *****
2025-12-11 15:40:34.660678 | controller | changed: [instance]
2025-12-11 15:40:34.899258 | controller |
2025-12-11 15:40:34.899291 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-12-11 15:40:34.899299 | controller | Thursday 11 December 2025  15:40:34 +0000 (0:00:00.229)       0:05:00.232 *****
2025-12-11 15:40:34.899309 | controller | changed: [instance]
2025-12-11 15:40:35.167927 | controller |
2025-12-11 15:40:35.167964 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-12-11 15:40:35.167972 | controller | Thursday 11 December 2025  15:40:34 +0000 (0:00:00.238)       0:05:00.471 *****
2025-12-11 15:40:35.167982 | controller | ok: [instance]
2025-12-11 15:40:35.394913 | controller |
2025-12-11 15:40:35.395035 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-12-11 15:40:35.395044 | controller | Thursday 11 December 2025  15:40:35 +0000 (0:00:00.268)       0:05:00.739 *****
2025-12-11 15:40:35.395056 | controller | ok: [instance]
2025-12-11 15:40:35.644692 | controller |
2025-12-11 15:40:35.644727 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-12-11 15:40:35.644735 | controller | Thursday 11 December 2025  15:40:35 +0000 (0:00:00.227)       0:05:00.966 *****
2025-12-11 15:40:35.644746 | controller | changed: [instance]
2025-12-11 15:40:36.434927 | controller |
2025-12-11 15:40:36.434962 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-12-11 15:40:36.434970 | controller | Thursday 11 December 2025  15:40:35 +0000 (0:00:00.249)       0:05:01.216 *****
2025-12-11 15:40:36.434980 | controller | changed: [instance] => (item=br-64v6)
2025-12-11 15:40:36.435251 | controller | changed: [instance] => (item=br-64v4)
2025-12-11 15:40:36.435264 | controller |
2025-12-11 15:40:37.357656 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-12-11 15:40:37.357689 | controller | Thursday 11 December 2025  15:40:36 +0000 (0:00:00.790)       0:05:02.007 *****
2025-12-11 15:40:37.357701 | controller | changed: [instance]
2025-12-11 15:40:37.391962 | controller |
2025-12-11 15:40:37.391981 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-12-11 15:40:37.391988 | controller | Thursday 11 December 2025  15:40:37 +0000 (0:00:00.922)       0:05:02.929 *****
2025-12-11 15:40:37.391997 | controller | ok: [instance]
2025-12-11 15:40:37.434843 | controller |
2025-12-11 15:40:37.434887 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-12-11 15:40:37.434895 | controller | Thursday 11 December 2025  15:40:37 +0000 (0:00:00.034)       0:05:02.964 *****
2025-12-11 15:40:37.434904 | controller |
2025-12-11 15:40:37.829030 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-12-11 15:40:37.829061 | controller | Thursday 11 December 2025  15:40:37 +0000 (0:00:00.042)       0:05:03.006 *****
2025-12-11 15:40:37.829073 | controller | ok: [instance] => (item=artifacts)
2025-12-11 15:40:39.202410 | controller | ok: [instance] => (item=logs)
2025-12-11 15:40:39.202449 | controller |
2025-12-11 15:40:39.202458 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-12-11 15:40:39.202464 | controller | Thursday 11 December 2025  15:40:37 +0000 (0:00:00.393)       0:05:03.400 *****
2025-12-11 15:40:39.202473 | controller | ok: [instance]
2025-12-11 15:40:39.397422 | controller |
2025-12-11 15:40:39.397464 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-12-11 15:40:39.397473 | controller | Thursday 11 December 2025  15:40:39 +0000 (0:00:01.373)       0:05:04.774 *****
2025-12-11 15:40:39.397484 | controller | changed: [instance]
2025-12-11 15:40:39.733351 | controller |
2025-12-11 15:40:39.733376 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-12-11 15:40:39.733385 | controller | Thursday 11 December 2025  15:40:39 +0000 (0:00:00.195)       0:05:04.969 *****
2025-12-11 15:40:39.733401 | controller | changed: [instance]
2025-12-11 15:40:40.103887 | controller |
2025-12-11 15:40:40.103909 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-12-11 15:40:40.103917 | controller | Thursday 11 December 2025  15:40:39 +0000 (0:00:00.336)       0:05:05.305 *****
2025-12-11 15:40:40.103926 | controller | changed: [instance]
2025-12-11 15:40:40.468554 | controller |
2025-12-11 15:40:40.468589 | controller | TASK [config_drive : Generate network-data] ************************************
2025-12-11 15:40:40.468597 | controller | Thursday 11 December 2025  15:40:40 +0000 (0:00:00.370)       0:05:05.676 *****
2025-12-11 15:40:40.468607 | controller | changed: [instance]
2025-12-11 15:40:40.648412 | controller |
2025-12-11 15:40:40.648433 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-12-11 15:40:40.648449 | controller | Thursday 11 December 2025  15:40:40 +0000 (0:00:00.364)       0:05:06.040 *****
2025-12-11 15:40:40.648458 | controller | ok: [instance]
2025-12-11 15:40:40.666954 | controller |
2025-12-11 15:40:40.666996 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-12-11 15:40:40.667006 | controller | Thursday 11 December 2025  15:40:40 +0000 (0:00:00.180)       0:05:06.220 *****
2025-12-11 15:40:40.667020 | controller | skipping: [instance]
2025-12-11 15:40:40.667062 | controller |
2025-12-11 15:40:40.667084 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-12-11 15:40:40.884771 | controller | Thursday 11 December 2025  15:40:40 +0000 (0:00:00.018)       0:05:06.239 *****
2025-12-11 15:40:40.884793 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-12-11 15:40:41.994433 | controller | changed: [instance]
2025-12-11 15:40:41.994476 | controller |
2025-12-11 15:40:41.994483 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-12-11 15:40:41.994490 | controller | Thursday 11 December 2025  15:40:40 +0000 (0:00:00.217)       0:05:06.456 *****
2025-12-11 15:40:41.994500 | controller | changed: [instance]
2025-12-11 15:40:42.555887 | controller |
2025-12-11 15:40:42.555927 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-12-11 15:40:42.555935 | controller | Thursday 11 December 2025  15:40:41 +0000 (0:00:01.109)       0:05:07.566 *****
2025-12-11 15:40:42.555946 | controller | changed: [instance]
2025-12-11 15:40:42.580565 | controller |
2025-12-11 15:40:42.580590 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-12-11 15:40:42.580598 | controller | Thursday 11 December 2025  15:40:42 +0000 (0:00:00.561)       0:05:08.127 *****
2025-12-11 15:40:42.580606 | controller | ok: [instance]
2025-12-11 15:40:42.620953 | controller |
2025-12-11 15:40:42.620988 | controller | TASK [Set MAC address facts] ***************************************************
2025-12-11 15:40:42.620996 | controller | Thursday 11 December 2025  15:40:42 +0000 (0:00:00.025)       0:05:08.152 *****
2025-12-11 15:40:42.621006 | controller | ok: [instance]
2025-12-11 15:40:42.621030 | controller |
2025-12-11 15:40:42.621038 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-12-11 15:40:42.621125 | controller | Thursday 11 December 2025  15:40:42 +0000 (0:00:00.039)       0:05:08.192 *****
2025-12-11 15:40:42.848260 | controller | changed: [instance]
2025-12-11 15:40:43.089936 | controller |
2025-12-11 15:40:43.089970 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-12-11 15:40:43.089978 | controller | Thursday 11 December 2025  15:40:42 +0000 (0:00:00.227)       0:05:08.420 *****
2025-12-11 15:40:43.089988 | controller | ok: [instance]
2025-12-11 15:40:43.090318 | controller |
2025-12-11 15:40:43.323888 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-12-11 15:40:43.323921 | controller | Thursday 11 December 2025  15:40:43 +0000 (0:00:00.241)       0:05:08.662 *****
2025-12-11 15:40:43.323932 | controller | ok: [instance]
2025-12-11 15:40:43.548991 | controller |
2025-12-11 15:40:43.549025 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-12-11 15:40:43.549041 | controller | Thursday 11 December 2025  15:40:43 +0000 (0:00:00.230)       0:05:08.892 *****
2025-12-11 15:40:43.549051 | controller | changed: [instance]
2025-12-11 15:40:43.868975 | controller |
2025-12-11 15:40:43.869012 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-12-11 15:40:43.869020 | controller | Thursday 11 December 2025  15:40:43 +0000 (0:00:00.226)       0:05:09.118 *****
2025-12-11 15:40:43.869030 | controller | changed: [instance]
2025-12-11 15:40:44.662779 | controller |
2025-12-11 15:40:44.662813 | controller | TASK [Restart firewalld.service] ***********************************************
2025-12-11 15:40:44.662821 | controller | Thursday 11 December 2025  15:40:43 +0000 (0:00:00.322)       0:05:09.441 *****
2025-12-11 15:40:44.662830 | controller | changed: [instance]
2025-12-11 15:40:44.695791 | controller |
2025-12-11 15:40:44.695813 | controller | TASK [Generate test node UUID] *************************************************
2025-12-11 15:40:44.695827 | controller | Thursday 11 December 2025  15:40:44 +0000 (0:00:00.790)       0:05:10.231 *****
2025-12-11 15:40:44.695836 | controller | ok: [instance]
2025-12-11 15:40:53.057846 | controller |
2025-12-11 15:40:53.057974 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-12-11 15:40:53.057985 | controller | Thursday 11 December 2025  15:40:44 +0000 (0:00:00.035)       0:05:10.267 *****
2025-12-11 15:40:53.057998 | controller | changed: [instance]
2025-12-11 15:40:53.137768 | controller |
2025-12-11 15:40:53.137798 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-12-11 15:40:53.137811 | controller | Thursday 11 December 2025  15:40:53 +0000 (0:00:08.361)       0:05:18.629 *****
2025-12-11 15:40:53.137822 | controller |
2025-12-11 15:40:53.562238 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-12-11 15:40:53.562285 | controller | Thursday 11 December 2025  15:40:53 +0000 (0:00:00.080)       0:05:18.709 *****
2025-12-11 15:40:53.562302 | controller | ok: [instance] => (item=artifacts)
2025-12-11 15:40:54.849543 | controller | ok: [instance] => (item=logs)
2025-12-11 15:40:54.849613 | controller |
2025-12-11 15:40:54.849643 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-12-11 15:40:54.849650 | controller | Thursday 11 December 2025  15:40:53 +0000 (0:00:00.423)       0:05:19.133 *****
2025-12-11 15:40:54.849679 | controller | ok: [instance]
2025-12-11 15:40:54.850120 | controller |
2025-12-11 15:40:54.850455 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-12-11 15:40:54.850820 | controller | Thursday 11 December 2025  15:40:54 +0000 (0:00:01.288)       0:05:20.421 *****
2025-12-11 15:40:55.058494 | controller | changed: [instance]
2025-12-11 15:40:55.058840 | controller |
2025-12-11 15:40:55.059242 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-12-11 15:40:55.059543 | controller | Thursday 11 December 2025  15:40:55 +0000 (0:00:00.209)       0:05:20.630 *****
2025-12-11 15:40:55.409952 | controller | changed: [instance]
2025-12-11 15:40:55.410354 | controller |
2025-12-11 15:40:55.410745 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-12-11 15:40:55.411072 | controller | Thursday 11 December 2025  15:40:55 +0000 (0:00:00.351)       0:05:20.982 *****
2025-12-11 15:40:55.816695 | controller | changed: [instance]
2025-12-11 15:40:56.195293 | controller |
2025-12-11 15:40:56.195329 | controller | TASK [config_drive : Generate network-data] ************************************
2025-12-11 15:40:56.195338 | controller | Thursday 11 December 2025  15:40:55 +0000 (0:00:00.400)       0:05:21.382 *****
2025-12-11 15:40:56.195347 | controller | changed: [instance]
2025-12-11 15:40:56.395214 | controller |
2025-12-11 15:40:56.395255 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-12-11 15:40:56.395265 | controller | Thursday 11 December 2025  15:40:56 +0000 (0:00:00.384)       0:05:21.767 *****
2025-12-11 15:40:56.395277 | controller | ok: [instance]
2025-12-11 15:40:56.422098 | controller |
2025-12-11 15:40:56.422127 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-12-11 15:40:56.422135 | controller | Thursday 11 December 2025  15:40:56 +0000 (0:00:00.199)       0:05:21.967 *****
2025-12-11 15:40:56.422145 | controller | skipping: [instance]
2025-12-11 15:40:56.636941 | controller |
2025-12-11 15:40:56.636982 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-12-11 15:40:56.636990 | controller | Thursday 11 December 2025  15:40:56 +0000 (0:00:00.024)       0:05:21.991 *****
2025-12-11 15:40:56.637008 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-12-11 15:40:56.637026 | controller | changed: [instance]
2025-12-11 15:40:56.637034 | controller |
2025-12-11 15:40:56.637256 | controller | TASK [Define test-node VM] *****************************************************
2025-12-11 15:40:56.901991 | controller | Thursday 11 December 2025  15:40:56 +0000 (0:00:00.217)       0:05:22.209 *****
2025-12-11 15:40:56.902030 | controller | changed: [instance]
2025-12-11 15:40:57.363508 | controller |
2025-12-11 15:40:57.363543 | controller | TASK [Start test-node VM] ******************************************************
2025-12-11 15:40:57.363551 | controller | Thursday 11 December 2025  15:40:56 +0000 (0:00:00.264)       0:05:22.474 *****
2025-12-11 15:40:57.363561 | controller | changed: [instance]
2025-12-11 15:41:22.012291 | controller |
2025-12-11 15:41:22.012468 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-12-11 15:41:22.012478 | controller | Thursday 11 December 2025  15:40:57 +0000 (0:00:00.461)       0:05:22.935 *****
2025-12-11 15:41:22.012488 | controller | ok: [instance]
2025-12-11 15:41:22.012673 | controller |
2025-12-11 15:41:22.012685 | controller | TASK [Add test node to inventory] **********************************************
2025-12-11 15:41:22.012694 | controller | Thursday 11 December 2025  15:41:22 +0000 (0:00:24.646)       0:05:47.581 *****
2025-12-11 15:41:22.048485 | controller | changed: [instance]
2025-12-11 15:41:22.077798 | controller |
2025-12-11 15:41:22.077820 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-12-11 15:41:22.077828 | controller | Thursday 11 December 2025  15:41:22 +0000 (0:00:00.036)       0:05:47.618 *****
2025-12-11 15:41:22.077837 | controller | changed: [instance]
2025-12-11 15:41:42.107675 | controller |
2025-12-11 15:41:42.107905 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-12-11 15:41:42.107921 | controller | Thursday 11 December 2025  15:41:22 +0000 (0:00:00.031)       0:05:47.650 *****
2025-12-11 15:41:42.107933 | controller | Pausing for 20 seconds
2025-12-11 15:41:48.609053 | controller | ok: [instance]
2025-12-11 15:41:48.609090 | controller |
2025-12-11 15:41:48.609098 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-12-11 15:41:48.609105 | controller | Thursday 11 December 2025  15:41:42 +0000 (0:00:20.029)       0:06:07.679 *****
2025-12-11 15:41:48.609115 | controller | changed: [instance]
2025-12-11 15:41:49.703613 | controller |
2025-12-11 15:41:49.703646 | controller | TASK [Grab some info from the test node] ***************************************
2025-12-11 15:41:49.703654 | controller | Thursday 11 December 2025  15:41:48 +0000 (0:00:06.502)       0:06:14.181 *****
2025-12-11 15:41:49.703664 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-12-11 15:41:50.701382 | controller |
2025-12-11 15:41:50.701416 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-12-11 15:41:50.701424 | controller | Thursday 11 December 2025  15:41:49 +0000 (0:00:01.094)       0:06:15.275 *****
2025-12-11 15:41:50.701434 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-12-11 15:41:51.275455 | controller |
2025-12-11 15:41:51.275484 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-12-11 15:41:51.275491 | controller | Thursday 11 December 2025  15:41:50 +0000 (0:00:00.997)       0:06:16.273 *****
2025-12-11 15:41:51.275501 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-12-11 15:41:51.796747 | controller |
2025-12-11 15:41:51.796773 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-12-11 15:41:51.796780 | controller | Thursday 11 December 2025  15:41:51 +0000 (0:00:00.574)       0:06:16.847 *****
2025-12-11 15:41:51.796789 | controller | changed: [instance]
2025-12-11 15:41:52.119909 | controller |
2025-12-11 15:41:52.119939 | controller | TASK [Write test-node info to file] ********************************************
2025-12-11 15:41:52.119947 | controller | Thursday 11 December 2025  15:41:51 +0000 (0:00:00.521)       0:06:17.369 *****
2025-12-11 15:41:52.119956 | controller | changed: [instance]
2025-12-11 15:41:52.438325 | controller |
2025-12-11 15:41:52.438360 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-12-11 15:41:52.438368 | controller | Thursday 11 December 2025  15:41:52 +0000 (0:00:00.323)       0:06:17.692 *****
2025-12-11 15:41:52.438378 | controller | changed: [instance]
2025-12-11 15:41:52.774709 | controller |
2025-12-11 15:41:52.774740 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-12-11 15:41:52.774748 | controller | Thursday 11 December 2025  15:41:52 +0000 (0:00:00.318)       0:06:18.010 *****
2025-12-11 15:41:52.774757 | controller | changed: [instance]
2025-12-11 15:41:53.108987 | controller |
2025-12-11 15:41:53.109018 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-12-11 15:41:53.109026 | controller | Thursday 11 December 2025  15:41:52 +0000 (0:00:00.336)       0:06:18.346 *****
2025-12-11 15:41:53.109035 | controller | changed: [instance]
2025-12-11 15:41:53.414657 | controller |
2025-12-11 15:41:53.414688 | controller | TASK [Write hypervisor info to file] *******************************************
2025-12-11 15:41:53.414695 | controller | Thursday 11 December 2025  15:41:53 +0000 (0:00:00.334)       0:06:18.681 *****
2025-12-11 15:41:53.414705 | controller | changed: [instance]
2025-12-11 15:41:55.042659 | controller |
2025-12-11 15:41:55.042693 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-12-11 15:41:55.042701 | controller | Thursday 11 December 2025  15:41:53 +0000 (0:00:00.305)       0:06:18.986 *****
2025-12-11 15:41:55.042711 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-12-11 15:41:55.070382 | controller |
2025-12-11 15:41:55.070401 | controller | TASK [Debug the ping example.com result] ***************************************
2025-12-11 15:41:55.070409 | controller | Thursday 11 December 2025  15:41:55 +0000 (0:00:01.627)       0:06:20.614 *****
2025-12-11 15:41:55.070418 | controller | ok: [instance] => (item=0) =>
2025-12-11 15:41:55.089350 | controller |   msg: '0'
2025-12-11 15:41:55.089370 | 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=41.6 ms', '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=42.9 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 41.554/42.233/42.912/0.679 ms']) =>
2025-12-11 15:41:55.089378 | controller |   msg:
2025-12-11 15:41:55.089385 | controller |   - PING example.com(a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450)) 56 data bytes
2025-12-11 15:41:55.089391 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=1 ttl=47 time=41.6 ms'
2025-12-11 15:41:55.089397 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=42.9 ms'
2025-12-11 15:41:55.089403 | controller |   - ''
2025-12-11 15:41:55.089408 | controller |   - '--- example.com ping statistics ---'
2025-12-11 15:41:55.089414 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-12-11 15:41:55.089420 | controller |   - rtt min/avg/max/mdev = 41.554/42.233/42.912/0.679 ms
2025-12-11 15:41:55.089426 | controller | ok: [instance] => (item=[]) =>
2025-12-11 15:41:55.089431 | controller |   msg: []
2025-12-11 15:41:55.089437 | controller |
2025-12-11 15:41:55.089442 | controller | TASK [Set download test directory] *********************************************
2025-12-11 15:41:55.089448 | controller | Thursday 11 December 2025  15:41:55 +0000 (0:00:00.026)       0:06:20.641 *****
2025-12-11 15:41:55.089456 | controller | ok: [instance]
2025-12-11 15:41:57.276442 | controller |
2025-12-11 15:41:57.276475 | controller | TASK [Start HTTP server to serve the built image] ******************************
2025-12-11 15:41:57.276487 | controller | Thursday 11 December 2025  15:41:55 +0000 (0:00:00.020)       0:06:20.661 *****
2025-12-11 15:41:57.276497 | controller | changed: [instance]
2025-12-11 15:41:57.584269 | controller |
2025-12-11 15:41:57.584301 | controller | TASK [Verify HTTP server is running] *******************************************
2025-12-11 15:41:57.584319 | controller | Thursday 11 December 2025  15:41:57 +0000 (0:00:02.186)       0:06:22.848 *****
2025-12-11 15:41:57.584329 | controller | ok: [instance]
2025-12-11 15:41:57.634873 | controller |
2025-12-11 15:41:57.634899 | controller | TASK [Download nat64 appliance image from HTTP server] *************************
2025-12-11 15:41:57.634907 | controller | Thursday 11 December 2025  15:41:57 +0000 (0:00:00.307)       0:06:23.156 *****
2025-12-11 15:41:57.634917 | controller |
2025-12-11 15:41:57.974310 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-12-11 15:41:57.974335 | controller | Thursday 11 December 2025  15:41:57 +0000 (0:00:00.050)       0:06:23.207 *****
2025-12-11 15:41:57.974346 | controller | changed: [instance] => (item=artifacts)
2025-12-11 15:41:58.163413 | controller | changed: [instance] => (item=logs)
2025-12-11 15:41:58.163442 | controller |
2025-12-11 15:41:58.163449 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-12-11 15:41:58.163455 | controller | Thursday 11 December 2025  15:41:57 +0000 (0:00:00.339)       0:06:23.546 *****
2025-12-11 15:41:58.163465 | controller | changed: [instance]
2025-12-11 15:41:58.193317 | controller |
2025-12-11 15:41:58.193337 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-12-11 15:41:58.193345 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.189)       0:06:23.735 *****
2025-12-11 15:41:58.193354 | controller | skipping: [instance]
2025-12-11 15:41:58.222764 | controller |
2025-12-11 15:41:58.222781 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-12-11 15:41:58.222788 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.030)       0:06:23.765 *****
2025-12-11 15:41:58.222796 | controller | skipping: [instance]
2025-12-11 15:41:58.254983 | controller |
2025-12-11 15:41:58.254999 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-12-11 15:41:58.255006 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.029)       0:06:23.795 *****
2025-12-11 15:41:58.255015 | controller | skipping: [instance] => (item=elements/)
2025-12-11 15:41:58.282675 | controller | skipping: [instance] => (item=nat64-appliance.yaml)
2025-12-11 15:41:58.282691 | controller | skipping: [instance]
2025-12-11 15:41:58.282698 | controller |
2025-12-11 15:41:58.282703 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-12-11 15:41:58.282709 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.032)       0:06:23.827 *****
2025-12-11 15:41:58.282717 | controller | skipping: [instance]
2025-12-11 15:41:58.312468 | controller |
2025-12-11 15:41:58.312485 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-12-11 15:41:58.312492 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.027)       0:06:23.855 *****
2025-12-11 15:41:58.312500 | controller | skipping: [instance]
2025-12-11 15:42:02.121784 | controller |
2025-12-11 15:42:02.121816 | controller | TASK [nat64_appliance : Download pre-built NAT64 appliance image] **************
2025-12-11 15:42:02.121824 | controller | Thursday 11 December 2025  15:41:58 +0000 (0:00:00.029)       0:06:23.884 *****
2025-12-11 15:42:02.121834 | controller | changed: [instance]
2025-12-11 15:42:02.899043 | controller |
2025-12-11 15:42:02.899076 | controller | TASK [Verify downloaded image exists] ******************************************
2025-12-11 15:42:02.899084 | controller | Thursday 11 December 2025  15:42:02 +0000 (0:00:03.808)       0:06:27.694 *****
2025-12-11 15:42:02.899094 | controller | ok: [instance]
2025-12-11 15:42:03.696971 | controller |
2025-12-11 15:42:03.696995 | controller | TASK [Get built image info with checksum] **************************************
2025-12-11 15:42:03.697002 | controller | Thursday 11 December 2025  15:42:02 +0000 (0:00:00.777)       0:06:28.471 *****
2025-12-11 15:42:03.697010 | controller | ok: [instance]
2025-12-11 15:42:03.719987 | controller |
2025-12-11 15:42:03.720030 | controller | TASK [Show download test results] **********************************************
2025-12-11 15:42:03.720041 | controller | Thursday 11 December 2025  15:42:03 +0000 (0:00:00.798)       0:06:29.269 *****
2025-12-11 15:42:03.720055 | controller | ok: [instance] =>
2025-12-11 15:42:03.720097 | controller |   msg:
2025-12-11 15:42:03.720109 | controller |   - 'Built image: /home/zuul/ci-framework-data/nat64_appliance/nat64-appliance.qcow2'
2025-12-11 15:42:03.720678 | controller |   - '  Size: 859242496 bytes'
2025-12-11 15:42:03.720706 | controller |   - '  SHA256: 881fd1211a34c2eaa29494221c98dc0fbb38e33ea3b1c5d6876426dd7319c3aa'
2025-12-11 15:42:03.738624 | controller |   - 'Downloaded image: /home/zuul/ci-framework-data/nat64_download/nat64_appliance/nat64-appliance.qcow2'
2025-12-11 15:42:03.738657 | controller |   - '  Size: 859045888 bytes'
2025-12-11 15:42:03.738665 | controller |   - '  SHA256: 2215caf5b1045afa3227c63e5e8671b9e620e0d86e974f1f7abbf8a657ebd0cc'
2025-12-11 15:42:03.738680 | controller |
2025-12-11 15:42:03.738686 | controller | TASK [Verify images are identical using checksum] ******************************
2025-12-11 15:42:03.738695 | controller | Thursday 11 December 2025  15:42:03 +0000 (0:00:00.022)       0:06:29.292 *****
2025-12-11 15:42:03.738705 | controller | fatal: [instance]: FAILED! => changed=false
2025-12-11 15:42:03.738776 | controller |   assertion: _downloaded_image.stat.checksum == _built_image.stat.checksum
2025-12-11 15:42:03.738785 | controller |   evaluated_to: false
2025-12-11 15:42:03.738791 | controller |   msg: |-
2025-12-11 15:42:03.738796 | controller |     Downloaded image differs from built image!
2025-12-11 15:42:03.738804 | controller |     Built:      859242496 bytes, SHA256: 881fd1211a34c2eaa29494221c98dc0fbb38e33ea3b1c5d6876426dd7319c3aa
2025-12-11 15:42:03.742624 | controller |     Downloaded: 859045888 bytes, SHA256: 2215caf5b1045afa3227c63e5e8671b9e620e0d86e974f1f7abbf8a657ebd0cc
2025-12-11 15:42:03.742651 | controller |
2025-12-11 15:42:03.797946 | controller | PLAY RECAP *********************************************************************
2025-12-11 15:42:03.797965 | controller | instance                   : ok=83   changed=54   unreachable=0    failed=1    skipped=8    rescued=0    ignored=0
2025-12-11 15:42:03.797973 | controller |
2025-12-11 15:42:03.797978 | controller | Thursday 11 December 2025  15:42:03 +0000 (0:00:00.020)       0:06:29.312 *****
2025-12-11 15:42:03.797984 | controller | ===============================================================================
2025-12-11 15:42:03.797989 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 243.65s
2025-12-11 15:42:03.797994 | controller | Wait for test node to be reachable via ssh ----------------------------- 24.65s
2025-12-11 15:42:03.797999 | controller | Wait a little to let the test instance boot. --------------------------- 20.03s
2025-12-11 15:42:03.798004 | controller | Download latest image -------------------------------------------------- 19.71s
2025-12-11 15:42:03.798009 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir --------------- 9.52s
2025-12-11 15:42:03.798014 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.36s
2025-12-11 15:42:03.798019 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 7.70s
2025-12-11 15:42:03.798024 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.20s
2025-12-11 15:42:03.798029 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.50s
2025-12-11 15:42:03.798034 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.25s
2025-12-11 15:42:03.798040 | controller | nat64_appliance : Download pre-built NAT64 appliance image -------------- 3.81s
2025-12-11 15:42:03.798044 | controller | Start HTTP server to serve the built image ------------------------------ 2.19s
2025-12-11 15:42:03.798049 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.63s
2025-12-11 15:42:03.798054 | controller | discover_latest_image : Get latest image -------------------------------- 1.60s
2025-12-11 15:42:03.798059 | controller | config_drive : Install required RPM packages ---------------------------- 1.37s
2025-12-11 15:42:03.798064 | controller | config_drive : Install required RPM packages ---------------------------- 1.29s
2025-12-11 15:42:03.798069 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.11s
2025-12-11 15:42:03.798074 | controller | Grab some info from the test node --------------------------------------- 1.09s
2025-12-11 15:42:03.798079 | controller | Restart firewalld.service ----------------------------------------------- 1.03s
2025-12-11 15:42:03.798084 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.01s
2025-12-11 15:42:03.798096 | controller | CRITICAL Ansible return code was 2, command was: ['ansible-playbook', '--inventory', '/home/zuul/.cache/molecule/nat64_appliance/default/inventory', '--skip-tags', 'molecule-notest,notest', '/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/nat64_appliance/molecule/default/converge.yml']
2025-12-11 15:42:03.798485 | controller | WARNING  An error occurred during the test sequence action: 'converge'. Cleaning up.
2025-12-11 15:42:03.806304 | controller | INFO     Running default > cleanup
2025-12-11 15:42:04.223731 | controller |
2025-12-11 15:42:04.224027 | controller | PLAY [Cleanup] *****************************************************************
2025-12-11 15:42:04.224161 | controller |
2025-12-11 15:42:04.224294 | controller | TASK [Gathering Facts] *********************************************************
2025-12-11 15:42:04.224425 | controller | Thursday 11 December 2025  15:42:04 +0000 (0:00:00.044)       0:00:00.044 *****
2025-12-11 15:42:05.121804 | controller | ok: [instance]
2025-12-11 15:42:05.665367 | controller |
2025-12-11 15:42:05.665398 | controller | TASK [Destroy the test-node] ***************************************************
2025-12-11 15:42:05.665406 | controller | Thursday 11 December 2025  15:42:05 +0000 (0:00:00.897)       0:00:00.942 *****
2025-12-11 15:42:05.665415 | controller | ok: [instance]
2025-12-11 15:42:05.879756 | controller |
2025-12-11 15:42:05.879781 | controller | TASK [Undefine the test-node] **************************************************
2025-12-11 15:42:05.879794 | controller | Thursday 11 December 2025  15:42:05 +0000 (0:00:00.544)       0:00:01.486 *****
2025-12-11 15:42:05.879803 | controller | ok: [instance]
2025-12-11 15:42:06.230620 | controller |
2025-12-11 15:42:06.230650 | controller | TASK [Destroy the test network] ************************************************
2025-12-11 15:42:06.230659 | controller | Thursday 11 December 2025  15:42:05 +0000 (0:00:00.214)       0:00:01.700 *****
2025-12-11 15:42:06.230668 | controller | ok: [instance]
2025-12-11 15:42:06.439676 | controller |
2025-12-11 15:42:06.439699 | controller | TASK [Undefine the test network] ***********************************************
2025-12-11 15:42:06.439708 | controller | Thursday 11 December 2025  15:42:06 +0000 (0:00:00.350)       0:00:02.051 *****
2025-12-11 15:42:06.439717 | controller | ok: [instance]
2025-12-11 15:42:06.471453 | controller |
2025-12-11 15:42:06.471478 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-12-11 15:42:06.471488 | controller | Thursday 11 December 2025  15:42:06 +0000 (0:00:00.209)       0:00:02.260 *****
2025-12-11 15:42:06.471500 | controller |
2025-12-11 15:42:06.743936 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-12-11 15:42:06.743965 | controller | Thursday 11 December 2025  15:42:06 +0000 (0:00:00.031)       0:00:02.292 *****
2025-12-11 15:42:06.743975 | controller | changed: [instance]
2025-12-11 15:42:06.744170 | controller |
2025-12-11 15:42:06.744205 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-12-11 15:42:07.009681 | controller | Thursday 11 December 2025  15:42:06 +0000 (0:00:00.272)       0:00:02.565 *****
2025-12-11 15:42:07.009703 | controller | ok: [instance]
2025-12-11 15:42:07.229938 | controller |
2025-12-11 15:42:07.229970 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-12-11 15:42:07.229977 | controller | Thursday 11 December 2025  15:42:07 +0000 (0:00:00.265)       0:00:02.830 *****
2025-12-11 15:42:07.229986 | controller | ok: [instance]
2025-12-11 15:42:07.447821 | controller |
2025-12-11 15:42:07.447869 | controller | TASK [nat64_appliance : Get nat64_appliance VM state] **************************
2025-12-11 15:42:07.447880 | controller | Thursday 11 December 2025  15:42:07 +0000 (0:00:00.220)       0:00:03.050 *****
2025-12-11 15:42:07.447891 | controller | ok: [instance]
2025-12-11 15:42:07.899911 | controller |
2025-12-11 15:42:07.899941 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-12-11 15:42:07.899949 | controller | Thursday 11 December 2025  15:42:07 +0000 (0:00:00.217)       0:00:03.268 *****
2025-12-11 15:42:07.899959 | controller | ok: [instance]
2025-12-11 15:42:08.115748 | controller |
2025-12-11 15:42:08.115773 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-12-11 15:42:08.115781 | controller | Thursday 11 December 2025  15:42:07 +0000 (0:00:00.451)       0:00:03.720 *****
2025-12-11 15:42:08.115790 | controller | ok: [instance]
2025-12-11 15:42:08.812963 | controller |
2025-12-11 15:42:08.812995 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-12-11 15:42:08.813003 | controller | Thursday 11 December 2025  15:42:08 +0000 (0:00:00.216)       0:00:03.936 *****
2025-12-11 15:42:08.813012 | controller | ok: [instance] => (item=nat64-net-v4)
2025-12-11 15:42:08.813029 | controller | ok: [instance] => (item=nat64-net-v6)
2025-12-11 15:42:08.813035 | controller |
2025-12-11 15:42:08.813040 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-12-11 15:42:08.813047 | controller | Thursday 11 December 2025  15:42:08 +0000 (0:00:00.696)       0:00:04.633 *****
2025-12-11 15:42:09.238000 | controller | ok: [instance] => (item=nat64-net-v4)
2025-12-11 15:42:09.238065 | controller | ok: [instance] => (item=nat64-net-v6)
2025-12-11 15:42:09.238076 | controller |
2025-12-11 15:42:09.238085 | controller | PLAY RECAP *********************************************************************
2025-12-11 15:42:09.238094 | controller | instance                   : ok=13   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-12-11 15:42:09.238101 | controller |
2025-12-11 15:42:09.238109 | controller | Thursday 11 December 2025  15:42:09 +0000 (0:00:00.424)       0:00:05.058 *****
2025-12-11 15:42:09.238117 | controller | ===============================================================================
2025-12-11 15:42:09.238124 | controller | Gathering Facts --------------------------------------------------------- 0.90s
2025-12-11 15:42:09.238132 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.70s
2025-12-11 15:42:09.238139 | controller | Destroy the test-node --------------------------------------------------- 0.54s
2025-12-11 15:42:09.238149 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.45s
2025-12-11 15:42:09.238179 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.42s
2025-12-11 15:42:09.239026 | controller | Destroy the test network ------------------------------------------------ 0.35s
2025-12-11 15:42:09.292538 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.27s
2025-12-11 15:42:09.292558 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.27s
2025-12-11 15:42:09.292566 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.22s
2025-12-11 15:42:09.292571 | controller | nat64_appliance : Get nat64_appliance VM state -------------------------- 0.22s
2025-12-11 15:42:09.292576 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.22s
2025-12-11 15:42:09.292582 | controller | Undefine the test-node -------------------------------------------------- 0.21s
2025-12-11 15:42:09.292587 | controller | Undefine the test network ----------------------------------------------- 0.21s
2025-12-11 15:42:09.292592 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-12-11 15:42:09.292610 | controller | INFO     Running default > destroy
2025-12-11 15:42:09.292959 | controller | WARNING  Skipping, instances are delegated.
2025-12-11 15:42:09.293281 | controller | INFO     Pruning extra files from scenario ephemeral directory
2025-12-11 15:42:09.294678 | controller | INFO     Writing /tmp/report.html report.
2025-12-11 15:42:09.402933 | [controller] Waiting on logger
2025-12-11 15:42:14.578507 | [controller] Waiting on logger
2025-12-11 15:42:25.010363 | [controller] Waiting on logger
2025-12-11 15:42:35.442543 | [controller] Waiting on logger
2025-12-11 15:42:39.369042 | [Zuul] Log Stream did not terminate
2025-12-11 15:42:39.369304 | controller | ERROR
2025-12-11 15:42:39.369437 | controller | {
2025-12-11 15:42:39.369491 | controller |   "delta": "0:09:17.371301",
2025-12-11 15:42:39.369527 | controller |   "end": "2025-12-11 15:42:09.335886",
2025-12-11 15:42:39.369559 | controller |   "msg": "non-zero return code",
2025-12-11 15:42:39.369607 | controller |   "rc": 1,
2025-12-11 15:42:39.369643 | controller |   "start": "2025-12-11 15:32:51.964585"
2025-12-11 15:42:39.369672 | controller | }
failure
2025-12-11 15:42:39.415467 | 
2025-12-11 15:42:39.415525 | PLAY RECAP
2025-12-11 15:42:39.415572 | controller | ok: 3 changed: 0 unreachable: 0 failed: 1 skipped: 1 rescued: 0 ignored: 0
2025-12-11 15:42:39.415610 | 
2025-12-11 15:42:39.474151 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-12-11 15:42:39.474960 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-12-11 15:42:39.959533 | 
2025-12-11 15:42:39.959647 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-12-11 15:42:39.978703 | 
2025-12-11 15:42:39.978771 | TASK [Filter out host if needed]
2025-12-11 15:42:39.986530 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-12-11 15:42:39.990600 | 
2025-12-11 15:42:39.990662 | TASK [Ensure file is present]
2025-12-11 15:42:40.272071 | controller | ok
2025-12-11 15:42:40.278544 | 
2025-12-11 15:42:40.278615 | TASK [Manage molecule report file]
2025-12-11 15:42:40.297309 | [controller] Waiting on logger
2025-12-11 15:42:49.650432 | [controller] Waiting on logger
2025-12-11 15:43:00.082566 | [controller] Waiting on logger
2025-12-11 15:43:09.463016 | [controller] Waiting on logger
2025-12-11 15:43:10.578159 | [Zuul] Log Stream did not terminate
2025-12-11 15:43:10.578381 | controller | changed
2025-12-11 15:43:10.584022 | 
2025-12-11 15:43:10.584118 | TASK [Check if we get ci-framework-data basedir]
2025-12-11 15:43:10.764754 | controller | ok
2025-12-11 15:43:10.769512 | 
2025-12-11 15:43:10.769570 | TASK [Create ci-framework-data log directory for zuul]
2025-12-11 15:43:11.051195 | controller | changed
2025-12-11 15:43:11.056212 | 
2025-12-11 15:43:11.056276 | TASK [Copy ci-framework interesting files]
2025-12-11 15:43:16.078371 | controller | changed
2025-12-11 15:43:16.083176 | 
2025-12-11 15:43:16.083235 | TASK [Get SELinux listing]
2025-12-11 15:43:16.101772 | [controller] Waiting on logger
2025-12-11 15:43:28.562470 | [controller] Waiting on logger
2025-12-11 15:43:38.994589 | [controller] Waiting on logger
2025-12-11 15:43:46.280871 | [Zuul] Log Stream did not terminate
2025-12-11 15:43:46.281109 | controller | changed
2025-12-11 15:43:46.286649 | 
2025-12-11 15:43:46.286725 | TASK [Generate log index]
2025-12-11 15:43:46.872846 | controller | changed
2025-12-11 15:43:46.877542 | 
2025-12-11 15:43:46.877605 | TASK [Get some env related data]
2025-12-11 15:43:46.897290 | [controller] Waiting on logger
2025-12-11 15:43:57.298750 | [controller] Waiting on logger
2025-12-11 15:44:06.642587 | [controller] Waiting on logger
2025-12-11 15:44:17.074452 | [controller] Waiting on logger
2025-12-11 15:44:18.113588 | [Zuul] Log Stream did not terminate
2025-12-11 15:44:18.114076 | controller | changed
2025-12-11 15:44:18.119373 | 
2025-12-11 15:44:18.119432 | TASK [Generate list of logs to collect in home directory]
2025-12-11 15:44:18.382811 | controller | ok: All paths examined
2025-12-11 15:44:18.387328 | 
2025-12-11 15:44:18.387386 | LOOP [Copy logs from home directory]
2025-12-11 15:44:18.666775 | controller | changed:
2025-12-11 15:44:18.666896 | controller | {
2025-12-11 15:44:18.666945 | controller |   "atime": 1765467154.2765932,
2025-12-11 15:44:18.666967 | controller |   "ctime": 1765467169.8510349,
2025-12-11 15:44:18.666985 | controller |   "dev": 64513,
2025-12-11 15:44:18.667001 | controller |   "gid": 1000,
2025-12-11 15:44:18.667015 | controller |   "gr_name": "zuul",
2025-12-11 15:44:18.667030 | controller |   "inode": 4329667,
2025-12-11 15:44:18.667044 | controller |   "isblk": false,
2025-12-11 15:44:18.667059 | controller |   "ischr": false,
2025-12-11 15:44:18.667073 | controller |   "isdir": false,
2025-12-11 15:44:18.667087 | controller |   "isfifo": false,
2025-12-11 15:44:18.667101 | controller |   "isgid": false,
2025-12-11 15:44:18.667114 | controller |   "islnk": false,
2025-12-11 15:44:18.667128 | controller |   "isreg": true,
2025-12-11 15:44:18.667141 | controller |   "issock": false,
2025-12-11 15:44:18.667155 | controller |   "isuid": false,
2025-12-11 15:44:18.667171 | controller |   "mode": "0644",
2025-12-11 15:44:18.667185 | controller |   "mtime": 1765467169.8510349,
2025-12-11 15:44:18.667199 | controller |   "nlink": 1,
2025-12-11 15:44:18.667212 | controller |   "path": "/home/zuul/ansible.log",
2025-12-11 15:44:18.667225 | controller |   "pw_name": "zuul",
2025-12-11 15:44:18.667238 | controller |   "rgrp": true,
2025-12-11 15:44:18.667251 | controller |   "roth": true,
2025-12-11 15:44:18.667264 | controller |   "rusr": true,
2025-12-11 15:44:18.667278 | controller |   "size": 6749,
2025-12-11 15:44:18.667291 | controller |   "uid": 1000,
2025-12-11 15:44:18.667305 | controller |   "wgrp": false,
2025-12-11 15:44:18.667318 | controller |   "woth": false,
2025-12-11 15:44:18.667330 | controller |   "wusr": true,
2025-12-11 15:44:18.667342 | controller |   "xgrp": false,
2025-12-11 15:44:18.667354 | controller |   "xoth": false,
2025-12-11 15:44:18.667366 | controller |   "xusr": false
2025-12-11 15:44:18.667378 | controller | }
2025-12-11 15:44:18.680598 | 
2025-12-11 15:44:18.680673 | TASK [Copy crio stats log file]
2025-12-11 15:44:18.694502 | controller | skipping: Conditional result was False
2025-12-11 15:44:18.699631 | 
2025-12-11 15:44:18.699690 | TASK [Get SELinux related data]
2025-12-11 15:44:18.718430 | [controller] Waiting on logger
2025-12-11 15:44:26.085366 | controller | ERROR
2025-12-11 15:44:26.085574 | controller | {
2025-12-11 15:44:26.085603 | controller |   "delta": "0:00:00.008651",
2025-12-11 15:44:26.085623 | controller |   "end": "2025-12-11 15:44:18.889009",
2025-12-11 15:44:26.085640 | controller |   "msg": "non-zero return code",
2025-12-11 15:44:26.085655 | controller |   "rc": 1,
2025-12-11 15:44:26.085670 | controller |   "start": "2025-12-11 15:44:18.880358"
2025-12-11 15:44:26.085685 | controller | }
2025-12-11 15:44:26.085706 | controller | ERROR: Ignoring Errors
2025-12-11 15:44:26.090562 | 
2025-12-11 15:44:26.090621 | TASK [Create system configuration directory]
2025-12-11 15:44:26.262816 | controller | changed
2025-12-11 15:44:26.267609 | 
2025-12-11 15:44:26.267672 | TASK [Get some of the system configurations]
2025-12-11 15:44:29.554418 | [controller] Waiting on logger
2025-12-11 15:44:31.295139 | controller | changed
2025-12-11 15:44:31.300206 | 
2025-12-11 15:44:31.300265 | TASK [Copy generated documentation if available]
2025-12-11 15:44:31.313595 | controller | skipping: Conditional result was False
2025-12-11 15:44:31.318445 | 
2025-12-11 15:44:31.318500 | TASK [Copy generated AsciiDoc documentation if available]
2025-12-11 15:44:31.331564 | controller | skipping: Conditional result was False
2025-12-11 15:44:31.336970 | 
2025-12-11 15:44:31.337026 | TASK [Compress logs bigger than 2MB]
2025-12-11 15:44:34.418508 | [controller] Waiting on logger
2025-12-11 15:44:44.850511 | [controller] Waiting on logger
2025-12-11 15:44:55.282399 | [controller] Waiting on logger
2025-12-11 15:45:01.533368 | [Zuul] Log Stream did not terminate
2025-12-11 15:45:01.533570 | controller | changed
2025-12-11 15:45:01.538520 | 
2025-12-11 15:45:01.538583 | TASK [Copy files from workspace on node]
2025-12-11 15:45:01.556036 | controller | ok
2025-12-11 15:45:01.576524 | 
2025-12-11 15:45:01.576589 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-11 15:45:01.589738 | controller | skipping: Conditional result was False
2025-12-11 15:45:01.594571 | 
2025-12-11 15:45:01.594631 | TASK [fetch-output : Set log path for single node]
2025-12-11 15:45:01.622151 | controller | ok
2025-12-11 15:45:01.627995 | 
2025-12-11 15:45:01.628058 | LOOP [fetch-output : Ensure local output dirs]
2025-12-11 15:45:01.815300 | controller -> localhost | ok: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/logs"
2025-12-11 15:45:01.815530 | controller -> localhost | changed: All items complete
2025-12-11 15:45:01.815562 | 
2025-12-11 15:45:01.993524 | controller -> localhost | changed: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/artifacts"
2025-12-11 15:45:02.164094 | controller -> localhost | changed: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/docs"
2025-12-11 15:45:02.175337 | 
2025-12-11 15:45:02.175424 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-11 15:45:02.708400 | controller | changed:
2025-12-11 15:45:02.708557 | controller | .d..t...... ./
2025-12-11 15:45:02.708584 | controller | >f+++++++++ README.html
2025-12-11 15:45:02.708604 | controller | >f+++++++++ ansible-execution.log
2025-12-11 15:45:02.708621 | controller | >f+++++++++ ansible.log
2025-12-11 15:45:02.708636 | controller | >f+++++++++ dmesg.log
2025-12-11 15:45:02.708652 | controller | >f+++++++++ installed-pkgs.log
2025-12-11 15:45:02.708667 | controller | >f+++++++++ python.log
2025-12-11 15:45:02.708683 | controller | >f+++++++++ registries.conf
2025-12-11 15:45:02.708698 | controller | >f+++++++++ report.html
2025-12-11 15:45:02.708713 | controller | >f+++++++++ selinux-denials.log
2025-12-11 15:45:02.708727 | controller | >f+++++++++ selinux-listing.log
2025-12-11 15:45:02.708741 | controller | cd+++++++++ ci-framework-data/
2025-12-11 15:45:02.708755 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-12-11 15:45:02.708779 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-12-11 15:45:02.708796 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-12-11 15:45:02.708810 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-12-11 15:45:02.708824 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-12-11 15:45:02.708837 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-12-11 15:45:02.708851 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/78cb3ef4-c2a1-5848-95bd-e910a7f60ff4/
2025-12-11 15:45:02.708864 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/78cb3ef4-c2a1-5848-95bd-e910a7f60ff4/meta-data
2025-12-11 15:45:02.708878 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/78cb3ef4-c2a1-5848-95bd-e910a7f60ff4/network-config
2025-12-11 15:45:02.708896 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/78cb3ef4-c2a1-5848-95bd-e910a7f60ff4/user-data
2025-12-11 15:45:02.708934 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7bca9446-4046-53ab-97a4-8fe31260cee8/
2025-12-11 15:45:02.708953 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7bca9446-4046-53ab-97a4-8fe31260cee8/meta-data
2025-12-11 15:45:02.708968 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7bca9446-4046-53ab-97a4-8fe31260cee8/network-config
2025-12-11 15:45:02.708981 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7bca9446-4046-53ab-97a4-8fe31260cee8/user-data
2025-12-11 15:45:02.708994 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-12-11 15:45:02.709007 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-12-11 15:45:02.709020 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-12-11 15:45:02.709032 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-12-11 15:45:02.709045 | controller | cd+++++++++ ci-framework-data/logs/
2025-12-11 15:45:02.709057 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-12-11 15:45:02.709069 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-12-11 15:45:02.709082 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-12-11 15:45:02.709094 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-12-11 15:45:02.709107 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-12-11 15:45:02.709120 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-12-11 15:45:02.709133 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-12-11 15:45:02.709145 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-12-11 15:45:02.709158 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-12-11 15:45:02.709171 | controller | cd+++++++++ registries.conf.d/
2025-12-11 15:45:02.709185 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-12-11 15:45:02.709198 | controller | cd+++++++++ system-config/
2025-12-11 15:45:02.709211 | controller | cd+++++++++ system-config/libvirt/
2025-12-11 15:45:02.709224 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-12-11 15:45:02.709236 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-12-11 15:45:02.709249 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-12-11 15:45:02.709261 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-12-11 15:45:02.709273 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-12-11 15:45:02.709285 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-12-11 15:45:02.709298 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-12-11 15:45:02.709310 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-12-11 15:45:02.709322 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-12-11 15:45:02.709335 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-12-11 15:45:02.709347 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-12-11 15:45:02.709360 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-12-11 15:45:02.709372 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-12-11 15:45:02.709385 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-12-11 15:45:02.709397 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-12-11 15:45:02.709410 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-12-11 15:45:03.053202 | controller | changed: .d..t...... ./
2025-12-11 15:45:03.389372 | controller | changed: .d..t...... ./
2025-12-11 15:45:03.404576 | 
2025-12-11 15:45:03.404681 | TASK [Return artifact to Zuul]
2025-12-11 15:45:03.433312 | controller | ok
2025-12-11 15:45:03.450364 | 
2025-12-11 15:45:03.450418 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-12-11 15:45:03.450509 | 
2025-12-11 15:45:03.450536 | PLAY RECAP
2025-12-11 15:45:03.450570 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-12-11 15:45:03.450589 | 
2025-12-11 15:45:03.519395 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-12-11 15:45:03.520158 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-11 15:45:03.988024 | 
2025-12-11 15:45:03.988123 | PLAY [all]
2025-12-11 15:45:04.005232 | 
2025-12-11 15:45:04.005300 | TASK [include_role : fetch-output]
2025-12-11 15:45:04.033675 | controller | ok
2025-12-11 15:45:04.048789 | 
2025-12-11 15:45:04.048874 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-11 15:45:04.083175 | controller | skipping: Conditional result was False
2025-12-11 15:45:04.088601 | 
2025-12-11 15:45:04.088670 | TASK [fetch-output : Set log path for single node]
2025-12-11 15:45:04.116403 | controller | ok
2025-12-11 15:45:04.120930 | 
2025-12-11 15:45:04.120996 | LOOP [fetch-output : Ensure local output dirs]
2025-12-11 15:45:04.423992 | controller -> localhost | ok: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/logs"
2025-12-11 15:45:04.594120 | controller -> localhost | ok: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/artifacts"
2025-12-11 15:45:04.759326 | controller -> localhost | ok: "/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/docs"
2025-12-11 15:45:04.767557 | 
2025-12-11 15:45:04.767654 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-11 15:45:05.249676 | controller | ok
2025-12-11 15:45:05.249886 | controller | ok: All items complete
2025-12-11 15:45:05.249937 | 
2025-12-11 15:45:05.611458 | controller | ok
2025-12-11 15:45:05.963074 | controller | ok
2025-12-11 15:45:05.976853 | 
2025-12-11 15:45:05.976936 | TASK [include_role : fetch-output-openshift]
2025-12-11 15:45:05.990716 | controller | skipping: Conditional result was False
2025-12-11 15:45:05.995876 | 
2025-12-11 15:45:05.995952 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-11 15:45:06.306792 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.005461
2025-12-11 15:45:06.481392 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.005713
2025-12-11 15:45:06.507331 | 
2025-12-11 15:45:06.507387 | PLAY [all]
2025-12-11 15:45:06.519998 | 
2025-12-11 15:45:06.520064 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-12-11 15:45:06.882514 | controller | changed
2025-12-11 15:45:06.902573 | 
2025-12-11 15:45:06.902619 | PLAY RECAP
2025-12-11 15:45:06.902669 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-12-11 15:45:06.902689 | 
2025-12-11 15:45:06.968825 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-11 15:45:06.969594 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-12-11 15:45:07.474821 | 
2025-12-11 15:45:07.474988 | PLAY [localhost]
2025-12-11 15:45:07.491388 | 
2025-12-11 15:45:07.491458 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-11 15:45:07.790476 | localhost | changed
2025-12-11 15:45:07.794948 | 
2025-12-11 15:45:07.795029 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-11 15:45:07.812324 | localhost | ok
2025-12-11 15:45:07.819958 | 
2025-12-11 15:45:07.820028 | TASK [add-fileserver : Create SSH private key tempfile]
2025-12-11 15:45:08.089858 | localhost | changed
2025-12-11 15:45:08.095094 | 
2025-12-11 15:45:08.095158 | TASK [add-fileserver : Create SSH private key from secret]
2025-12-11 15:45:08.588567 | localhost | changed
2025-12-11 15:45:08.593177 | 
2025-12-11 15:45:08.593240 | TASK [add-fileserver : Add fileserver ssh key]
2025-12-11 15:45:08.894558 | localhost | Identity added: /var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/tmp/ansible.35kaq717 (/var/lib/zuul/builds/22aab5ab0d604d9fa8ec4fd2c4f9ac3b/work/tmp/ansible.35kaq717)
2025-12-11 15:45:08.894688 | localhost | ok: Runtime: 0:00:00.006075
2025-12-11 15:45:08.898378 | 
2025-12-11 15:45:08.898440 | TASK [add-fileserver : Remove SSH private key from disk]
2025-12-11 15:45:09.097660 | localhost | ok: Runtime: 0:00:00.004392
2025-12-11 15:45:09.101686 | 
2025-12-11 15:45:09.101746 | TASK [add-fileserver : Add fileserver to inventory]
2025-12-11 15:45:09.149127 | localhost | changed
2025-12-11 15:45:09.153573 | 
2025-12-11 15:45:09.153632 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-12-11 15:45:09.443241 | localhost | changed
2025-12-11 15:45:09.460861 | 
2025-12-11 15:45:09.460945 | PLAY [localhost]
2025-12-11 15:45:09.471474 | 
2025-12-11 15:45:09.471541 | TASK [Generate bulk log download script]
2025-12-11 15:45:09.489433 | localhost | ok
2025-12-11 15:45:09.499625 | 
2025-12-11 15:45:09.499687 | TASK [local-log-download : Check API endpoint is defined]
2025-12-11 15:45:09.526411 | localhost | ok: All assertions passed
2025-12-11 15:45:09.530362 | 
2025-12-11 15:45:09.530421 | TASK [local-log-download : Create download script]
2025-12-11 15:45:09.846987 | localhost -> localhost | changed
2025-12-11 15:45:09.855221 | 
2025-12-11 15:45:09.855296 | TASK [Register quick-download link]
2025-12-11 15:45:09.872257 | localhost | ok
2025-12-11 15:45:09.905527 | 
2025-12-11 15:45:09.905594 | PLAY [logserver.rdoproject.org]
2025-12-11 15:45:09.914284 | 
2025-12-11 15:45:09.914340 | TASK [Set zuul-log-path fact]
2025-12-11 15:45:09.929784 | logserver.rdoproject.org | ok
2025-12-11 15:45:09.937804 | 
2025-12-11 15:45:09.937867 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-11 15:45:09.953862 | logserver.rdoproject.org | ok
2025-12-11 15:45:09.958624 | 
2025-12-11 15:45:09.958683 | TASK [upload-logs : Create log directories]
2025-12-11 15:45:13.526418 | logserver.rdoproject.org | changed
2025-12-11 15:45:13.529137 | 
2025-12-11 15:45:13.529195 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-12-11 15:45:13.724801 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004504
2025-12-11 15:45:13.729113 | 
2025-12-11 15:45:13.729175 | TASK [upload-logs : Upload logs to log server]
2025-12-11 15:45:15.379490 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-12-11 15:45:15.382216 | 
2025-12-11 15:45:15.382277 | LOOP [upload-logs : Compress console log and json output]
2025-12-11 15:45:15.417854 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-11 15:45:15.425606 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-11 15:45:15.439386 | 
2025-12-11 15:45:15.439479 | LOOP [upload-logs : Upload compressed console log and json output]
2025-12-11 15:45:15.472206 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-11 15:45:15.472393 | 
2025-12-11 15:45:15.475272 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-11 15:45:15.486711 | 
2025-12-11 15:45:15.486799 | LOOP [upload-logs : Upload console log and json output]