2025-10-08 12:29:52.867699 | Job console starting...
2025-10-08 12:29:53.108637 | Updating repositories
2025-10-08 12:29:53.898630 | Preparing job workspace
2025-10-08 12:30:02.822356 | Running Ansible setup...
2025-10-08 12:30:06.025582 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 12:30:06.676387 | 
2025-10-08 12:30:06.676494 | PLAY [localhost]
2025-10-08 12:30:06.685011 | 
2025-10-08 12:30:06.685093 | TASK [Gathering Facts]
2025-10-08 12:30:07.651578 | localhost | ok
2025-10-08 12:30:07.665404 | 
2025-10-08 12:30:07.665506 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-08 12:30:08.004522 | localhost -> localhost | changed
2025-10-08 12:30:08.010279 | 
2025-10-08 12:30:08.010357 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-08 12:30:08.764708 | localhost -> localhost | changed
2025-10-08 12:30:08.779588 | 
2025-10-08 12:30:08.779807 | TASK [Setup log path fact]
2025-10-08 12:30:08.799085 | localhost | ok
2025-10-08 12:30:08.810686 | 
2025-10-08 12:30:08.810765 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 12:30:08.839430 | localhost | ok
2025-10-08 12:30:08.847896 | 
2025-10-08 12:30:08.848060 | TASK [emit-job-header : Print job information]
2025-10-08 12:30:08.875661 | # Job Information
2025-10-08 12:30:08.875823 | Ansible Version: 2.15.12
2025-10-08 12:30:08.875853 | Job: cifmw-molecule-nat64_appliance
2025-10-08 12:30:08.875875 | Pipeline: github-check
2025-10-08 12:30:08.875895 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-10-08 12:30:08.875936 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3368
2025-10-08 12:30:08.875975 | Log URL (when completed): https://logserver.rdoproject.org/d71/rdoproject.org/d71e3a06924c4080afcba226bfb0e709/
2025-10-08 12:30:08.875996 | Event ID: e452cdb0-a431-11f0-8caa-4725382b7326
2025-10-08 12:30:08.880187 | 
2025-10-08 12:30:08.880269 | LOOP [emit-job-header : Print node information]
2025-10-08 12:30:08.973030 | localhost | ok:
2025-10-08 12:30:08.973231 | localhost | # Node Information
2025-10-08 12:30:08.973265 | localhost | Inventory Hostname: controller
2025-10-08 12:30:08.973291 | localhost | Hostname: np0005476207
2025-10-08 12:30:08.973312 | localhost | Username: zuul
2025-10-08 12:30:08.973333 | localhost | Distro: CentOS 9
2025-10-08 12:30:08.973351 | localhost | Provider: ibm-bm4-nodepool
2025-10-08 12:30:08.973369 | localhost | Region: regionOne
2025-10-08 12:30:08.973387 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-10-08 12:30:08.973405 | localhost | Product Name: OpenStack Compute
2025-10-08 12:30:08.973434 | localhost | Interface IP: 192.168.26.229
2025-10-08 12:30:08.995511 | 
2025-10-08 12:30:08.995601 | PLAY [all]
2025-10-08 12:30:09.003271 | 
2025-10-08 12:30:09.003408 | TASK [Gather network facts]
2025-10-08 12:30:09.362686 | controller | ok
2025-10-08 12:30:09.387237 | 
2025-10-08 12:30:09.387347 | TASK [include_role : start-zuul-console]
2025-10-08 12:30:09.418252 | controller | ok
2025-10-08 12:30:09.459838 | 
2025-10-08 12:30:09.459966 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-08 12:30:09.872252 | controller | ok
2025-10-08 12:30:09.886114 | 
2025-10-08 12:30:09.886196 | TASK [include_role : add-build-sshkey]
2025-10-08 12:30:09.919754 | controller | ok
2025-10-08 12:30:09.938618 | 
2025-10-08 12:30:09.938727 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-08 12:30:10.245755 | controller -> localhost | ok
2025-10-08 12:30:10.252383 | 
2025-10-08 12:30:10.252461 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-08 12:30:10.281050 | controller | ok
2025-10-08 12:30:10.300437 | controller | included: /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-08 12:30:10.305947 | 
2025-10-08 12:30:10.306050 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-08 12:30:10.949341 | controller -> localhost | Generating public/private rsa key pair.
2025-10-08 12:30:10.949549 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/d71e3a06924c4080afcba226bfb0e709_id_rsa.
2025-10-08 12:30:10.949597 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/d71e3a06924c4080afcba226bfb0e709_id_rsa.pub.
2025-10-08 12:30:10.949625 | controller -> localhost | The key fingerprint is:
2025-10-08 12:30:10.949649 | controller -> localhost | SHA256:G3devLHEgklwJUt4I+iVx4GAikOQWAu4R4MqsQ8dUwc zuul-build-sshkey
2025-10-08 12:30:10.949673 | controller -> localhost | The key's randomart image is:
2025-10-08 12:30:10.949706 | controller -> localhost | +---[RSA 3072]----+
2025-10-08 12:30:10.949726 | controller -> localhost | |*+..Eooo.==o.    |
2025-10-08 12:30:10.949747 | controller -> localhost | |*o=.... *+=o     |
2025-10-08 12:30:10.949765 | controller -> localhost | |oB.= . . +o.     |
2025-10-08 12:30:10.949785 | controller -> localhost | |O +   .  . o o   |
2025-10-08 12:30:10.949804 | controller -> localhost | |.=      S + o *  |
2025-10-08 12:30:10.949822 | controller -> localhost | |  .      + o + + |
2025-10-08 12:30:10.949840 | controller -> localhost | |        .   . o  |
2025-10-08 12:30:10.949859 | controller -> localhost | |                 |
2025-10-08 12:30:10.949877 | controller -> localhost | |                 |
2025-10-08 12:30:10.949895 | controller -> localhost | +----[SHA256]-----+
2025-10-08 12:30:10.950164 | controller -> localhost | ok: Runtime: 0:00:00.250666
2025-10-08 12:30:10.957608 | 
2025-10-08 12:30:10.957675 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-08 12:30:10.976214 | controller | ok
2025-10-08 12:30:10.986241 | controller | included: /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-08 12:30:10.995004 | 
2025-10-08 12:30:10.995070 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-08 12:30:11.019157 | controller | skipping: Conditional result was False
2025-10-08 12:30:11.029749 | 
2025-10-08 12:30:11.029822 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-08 12:30:11.465547 | controller | changed
2025-10-08 12:30:11.470762 | 
2025-10-08 12:30:11.470838 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-08 12:30:11.658128 | controller | ok
2025-10-08 12:30:11.663172 | 
2025-10-08 12:30:11.663255 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-08 12:30:12.219933 | controller | changed
2025-10-08 12:30:12.225263 | 
2025-10-08 12:30:12.225344 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-08 12:30:12.788028 | controller | changed
2025-10-08 12:30:12.794521 | 
2025-10-08 12:30:12.794604 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-08 12:30:12.808777 | controller | skipping: Conditional result was False
2025-10-08 12:30:12.819458 | 
2025-10-08 12:30:12.819539 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-08 12:30:13.185476 | controller -> localhost | changed
2025-10-08 12:30:13.195776 | 
2025-10-08 12:30:13.195871 | TASK [add-build-sshkey : Add back temp key]
2025-10-08 12:30:13.425945 | controller -> localhost | Identity added: /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/d71e3a06924c4080afcba226bfb0e709_id_rsa (zuul-build-sshkey)
2025-10-08 12:30:13.426138 | controller -> localhost | ok: Runtime: 0:00:00.007505
2025-10-08 12:30:13.431729 | 
2025-10-08 12:30:13.431796 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-08 12:30:13.743901 | controller | ok
2025-10-08 12:30:13.748447 | 
2025-10-08 12:30:13.748511 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-08 12:30:13.772187 | controller | skipping: Conditional result was False
2025-10-08 12:30:13.781305 | 
2025-10-08 12:30:13.781373 | TASK [include_role : validate-host]
2025-10-08 12:30:13.800651 | controller | ok
2025-10-08 12:30:13.818858 | 
2025-10-08 12:30:13.818941 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-08 12:30:13.846817 | controller | ok
2025-10-08 12:30:13.851418 | 
2025-10-08 12:30:13.851479 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-08 12:30:14.068497 | controller -> localhost | ok
2025-10-08 12:30:14.076264 | 
2025-10-08 12:30:14.076345 | TASK [validate-host : Collect information about the host]
2025-10-08 12:30:14.663236 | controller | ok
2025-10-08 12:30:14.678587 | 
2025-10-08 12:30:14.678718 | TASK [validate-host : Sanitize hostname]
2025-10-08 12:30:14.804195 | controller | ok
2025-10-08 12:30:14.810202 | 
2025-10-08 12:30:14.810292 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-08 12:30:15.307442 | controller -> localhost | changed
2025-10-08 12:30:15.317006 | 
2025-10-08 12:30:15.317092 | TASK [validate-host : Collect information about zuul worker]
2025-10-08 12:30:15.715930 | controller | ok
2025-10-08 12:30:15.720503 | 
2025-10-08 12:30:15.720575 | TASK [validate-host : Write out all zuul information for each host]
2025-10-08 12:30:16.152896 | controller -> localhost | changed
2025-10-08 12:30:16.164809 | 
2025-10-08 12:30:16.164886 | TASK [include_role : prepare-workspace-openshift]
2025-10-08 12:30:16.178305 | controller | skipping: Conditional result was False
2025-10-08 12:30:16.183280 | 
2025-10-08 12:30:16.183344 | TASK [include_role : remove-zuul-sshkey]
2025-10-08 12:30:16.196121 | controller | skipping: Conditional result was False
2025-10-08 12:30:16.201416 | 
2025-10-08 12:30:16.201487 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-08 12:30:16.388217 | controller | ok: "logs"
2025-10-08 12:30:16.388439 | controller | ok: All items complete
2025-10-08 12:30:16.388469 | 
2025-10-08 12:30:16.546643 | controller | ok: "artifacts"
2025-10-08 12:30:16.708841 | controller | ok: "docs"
2025-10-08 12:30:16.716650 | 
2025-10-08 12:30:16.716746 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-08 12:30:16.910791 | controller | changed: "logs"
2025-10-08 12:30:17.078456 | controller | changed: "artifacts"
2025-10-08 12:30:17.245821 | controller | changed: "docs"
2025-10-08 12:30:17.278070 | 
2025-10-08 12:30:17.278157 | PLAY RECAP
2025-10-08 12:30:17.278209 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 12:30:17.278239 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 12:30:17.278260 | 
2025-10-08 12:30:17.374751 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 12:30:17.378079 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 12:30:18.113997 | 
2025-10-08 12:30:18.114118 | PLAY [all]
2025-10-08 12:30:18.152801 | 
2025-10-08 12:30:18.152979 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 12:30:18.223816 | controller | ok
2025-10-08 12:30:18.234490 | 
2025-10-08 12:30:18.234613 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 12:30:18.603304 | controller | changed
2025-10-08 12:30:18.611103 | 
2025-10-08 12:30:18.611287 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 12:30:19.526078 | controller | changed
2025-10-08 12:30:19.540681 | 
2025-10-08 12:30:19.540771 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-10-08 12:30:19.935072 | controller | changed:
2025-10-08 12:30:19.935236 | controller | {
2025-10-08 12:30:19.935266 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-10-08 12:30:19.935295 | controller | }
2025-10-08 12:30:20.143059 | controller | changed:
2025-10-08 12:30:20.143143 | controller | {
2025-10-08 12:30:20.143174 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-10-08 12:30:20.143198 | controller | }
2025-10-08 12:30:20.364565 | controller | changed:
2025-10-08 12:30:20.364664 | controller | {
2025-10-08 12:30:20.364692 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-10-08 12:30:20.364715 | controller | }
2025-10-08 12:30:20.585057 | controller | changed:
2025-10-08 12:30:20.585150 | controller | {
2025-10-08 12:30:20.585178 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-10-08 12:30:20.585201 | controller | }
2025-10-08 12:30:20.815634 | controller | changed:
2025-10-08 12:30:20.815726 | controller | {
2025-10-08 12:30:20.815755 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-10-08 12:30:20.815778 | controller | }
2025-10-08 12:30:21.027426 | controller | changed:
2025-10-08 12:30:21.027513 | controller | {
2025-10-08 12:30:21.027542 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-10-08 12:30:21.027564 | controller | }
2025-10-08 12:30:21.254129 | controller | changed:
2025-10-08 12:30:21.254358 | controller | {
2025-10-08 12:30:21.254403 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2025-10-08 12:30:21.254430 | controller | }
2025-10-08 12:30:21.459802 | controller | changed:
2025-10-08 12:30:21.459882 | controller | {
2025-10-08 12:30:21.459937 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2025-10-08 12:30:21.459983 | controller | }
2025-10-08 12:30:21.692584 | controller | changed:
2025-10-08 12:30:21.692685 | controller | {
2025-10-08 12:30:21.692722 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-10-08 12:30:21.692752 | controller | }
2025-10-08 12:30:21.894884 | controller | changed:
2025-10-08 12:30:21.895000 | controller | {
2025-10-08 12:30:21.895029 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-10-08 12:30:21.895051 | controller | }
2025-10-08 12:30:22.109467 | controller | changed:
2025-10-08 12:30:22.109559 | controller | {
2025-10-08 12:30:22.109587 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-10-08 12:30:22.109609 | controller | }
2025-10-08 12:30:22.319299 | controller | changed:
2025-10-08 12:30:22.319388 | controller | {
2025-10-08 12:30:22.319420 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-10-08 12:30:22.319444 | controller | }
2025-10-08 12:30:22.530296 | controller | changed:
2025-10-08 12:30:22.530389 | controller | {
2025-10-08 12:30:22.530418 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-10-08 12:30:22.530440 | controller | }
2025-10-08 12:30:22.742388 | controller | changed:
2025-10-08 12:30:22.742480 | controller | {
2025-10-08 12:30:22.742511 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-10-08 12:30:22.742533 | controller | }
2025-10-08 12:30:22.960702 | controller | changed:
2025-10-08 12:30:22.960778 | controller | {
2025-10-08 12:30:22.960806 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-10-08 12:30:22.960828 | controller | }
2025-10-08 12:30:23.170506 | controller | changed:
2025-10-08 12:30:23.170591 | controller | {
2025-10-08 12:30:23.170629 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-10-08 12:30:23.170658 | controller | }
2025-10-08 12:30:23.376796 | controller | changed:
2025-10-08 12:30:23.376888 | controller | {
2025-10-08 12:30:23.376961 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2025-10-08 12:30:23.376989 | controller | }
2025-10-08 12:30:23.586556 | controller | changed:
2025-10-08 12:30:23.586720 | controller | {
2025-10-08 12:30:23.586760 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2025-10-08 12:30:23.586792 | controller | }
2025-10-08 12:30:23.804218 | controller | changed:
2025-10-08 12:30:23.804523 | controller | {
2025-10-08 12:30:23.804568 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-10-08 12:30:23.804593 | controller | }
2025-10-08 12:30:24.024316 | controller | changed:
2025-10-08 12:30:24.024426 | controller | {
2025-10-08 12:30:24.024457 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-10-08 12:30:24.024481 | controller | }
2025-10-08 12:30:24.244648 | controller | changed:
2025-10-08 12:30:24.244736 | controller | {
2025-10-08 12:30:24.244765 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-10-08 12:30:24.244788 | controller | }
2025-10-08 12:30:24.453357 | controller | changed:
2025-10-08 12:30:24.453446 | controller | {
2025-10-08 12:30:24.453476 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-10-08 12:30:24.453497 | controller | }
2025-10-08 12:30:24.662295 | controller | changed:
2025-10-08 12:30:24.662377 | controller | {
2025-10-08 12:30:24.662407 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2025-10-08 12:30:24.662430 | controller | }
2025-10-08 12:30:24.880875 | controller | changed:
2025-10-08 12:30:24.881003 | controller | {
2025-10-08 12:30:24.881032 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-10-08 12:30:24.881053 | controller | }
2025-10-08 12:30:25.100127 | controller | changed:
2025-10-08 12:30:25.100216 | controller | {
2025-10-08 12:30:25.100246 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-10-08 12:30:25.100267 | controller | }
2025-10-08 12:30:25.323925 | controller | changed:
2025-10-08 12:30:25.324041 | controller | {
2025-10-08 12:30:25.324077 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-10-08 12:30:25.324106 | controller | }
2025-10-08 12:30:25.350162 | 
2025-10-08 12:30:25.350264 | TASK [Set timezone to UTC]
2025-10-08 12:30:25.754427 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-10-08 12:30:25.763605 | 
2025-10-08 12:30:25.763703 | TASK [Create nodepool directory]
2025-10-08 12:30:26.021790 | controller | changed
2025-10-08 12:30:26.028291 | 
2025-10-08 12:30:26.028388 | TASK [Create nodepool sub_nodes file]
2025-10-08 12:30:26.592484 | controller | changed
2025-10-08 12:30:26.602126 | 
2025-10-08 12:30:26.602220 | TASK [Create nodepool sub_nodes_private file]
2025-10-08 12:30:27.149447 | controller | changed
2025-10-08 12:30:27.154678 | 
2025-10-08 12:30:27.154762 | LOOP [Populate nodepool sub_nodes file]
2025-10-08 12:30:27.184278 | 
2025-10-08 12:30:27.184435 | LOOP [Populate nodepool sub_nodes_private file]
2025-10-08 12:30:27.214478 | 
2025-10-08 12:30:27.214641 | TASK [Create nodepool primary file]
2025-10-08 12:30:27.250728 | controller | skipping: Conditional result was False
2025-10-08 12:30:27.256197 | 
2025-10-08 12:30:27.256290 | TASK [Create nodepool node_private for this node]
2025-10-08 12:30:27.897332 | controller | changed
2025-10-08 12:30:27.909653 | 
2025-10-08 12:30:27.909744 | LOOP [Copy ssh keys to nodepool directory]
2025-10-08 12:30:28.344618 | controller | ok: Item: id_rsa Runtime: 0:00:00.005661
2025-10-08 12:30:28.344778 | 
2025-10-08 12:30:28.520960 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005118
2025-10-08 12:30:28.529458 | 
2025-10-08 12:30:28.529560 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-10-08 12:30:29.191031 | controller | changed
2025-10-08 12:30:29.196059 | 
2025-10-08 12:30:29.196127 | TASK [Validate sudoers config after edits]
2025-10-08 12:30:29.504044 | controller | /etc/sudoers: parsed OK
2025-10-08 12:30:29.504150 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-10-08 12:30:29.504161 | controller | /etc/sudoers.d/zuul: parsed OK
2025-10-08 12:30:29.504167 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-10-08 12:30:29.762080 | controller | ok: Runtime: 0:00:00.004822
2025-10-08 12:30:29.772295 | 
2025-10-08 12:30:29.772391 | TASK [Show the environment passed in to job shell scripts]
2025-10-08 12:30:30.061361 | controller | SHELL=/bin/bash
2025-10-08 12:30:30.061410 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-10-08 12:30:30.061439 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-10-08 12:30:30.061446 | controller | ZUUL_CHANGES=openstack-k8s-operators/edpm-ansible:main:refs/changes/42/1042/4d1575d1c5aa317d07bf95973aac6faacde3d75b^openstack-k8s-operators/ci-framework:main:refs/changes/68/3368/a7a306bfcc713c1569b93e3182b828584aee713d
2025-10-08 12:30:30.061454 | controller | PWD=/home/zuul
2025-10-08 12:30:30.061459 | controller | ZUUL_PIPELINE=github-check
2025-10-08 12:30:30.061464 | controller | LOGNAME=zuul
2025-10-08 12:30:30.061470 | controller | XDG_SESSION_TYPE=tty
2025-10-08 12:30:30.061510 | controller | _=/usr/bin/env
2025-10-08 12:30:30.061519 | controller | MOTD_SHOWN=pam
2025-10-08 12:30:30.061524 | controller | HOME=/home/zuul
2025-10-08 12:30:30.061529 | controller | LANG=en_US.UTF-8
2025-10-08 12:30:30.061535 | controller | SSH_CONNECTION=192.168.26.12 51014 192.168.26.229 22
2025-10-08 12:30:30.061540 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2025-10-08 12:30:30.061545 | controller | ZUUL_CHANGE_IDS=1042,4d1575d1c5aa317d07bf95973aac6faacde3d75b 3368,a7a306bfcc713c1569b93e3182b828584aee713d
2025-10-08 12:30:30.061551 | controller | WORKSPACE=/home/zuul/workspace
2025-10-08 12:30:30.061556 | controller | XDG_SESSION_CLASS=user
2025-10-08 12:30:30.061561 | controller | SELINUX_ROLE_REQUESTED=
2025-10-08 12:30:30.061567 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-10-08 12:30:30.061572 | controller | USER=zuul
2025-10-08 12:30:30.061577 | controller | ZUUL_VOTING=True
2025-10-08 12:30:30.061582 | controller | BUILD_TIMEOUT=1800000
2025-10-08 12:30:30.061587 | controller | SELINUX_USE_CURRENT_RANGE=
2025-10-08 12:30:30.061593 | controller | SHLVL=1
2025-10-08 12:30:30.061598 | controller | ZUUL_PATCHSET=a7a306bfcc713c1569b93e3182b828584aee713d
2025-10-08 12:30:30.061603 | controller | XDG_SESSION_ID=1
2025-10-08 12:30:30.061608 | controller | ZUUL_BRANCH=main
2025-10-08 12:30:30.061614 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-10-08 12:30:30.061619 | controller | SSH_CLIENT=192.168.26.12 51014 22
2025-10-08 12:30:30.061624 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-10-08 12:30:30.061629 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-10-08 12:30:30.061637 | controller | which_declare=declare -f
2025-10-08 12:30:30.061643 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-10-08 12:30:30.061648 | controller | SELINUX_LEVEL_REQUESTED=
2025-10-08 12:30:30.061654 | controller | ZUUL_CHANGE=3368
2025-10-08 12:30:30.061659 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-10-08 12:30:30.061664 | controller | ZUUL_UUID=d71e3a06924c4080afcba226bfb0e709
2025-10-08 12:30:30.061670 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-10-08 12:30:30.061675 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-10-08 12:30:30.061680 | controller | }
2025-10-08 12:30:30.328967 | controller | ok: Runtime: 0:00:00.005939
2025-10-08 12:30:30.334625 | 
2025-10-08 12:30:30.334719 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-10-08 12:30:30.368503 | controller | skipping: Conditional result was False
2025-10-08 12:30:30.374340 | 
2025-10-08 12:30:30.374410 | TASK [Symlink /home/zuul-worker/workspace]
2025-10-08 12:30:30.937888 | controller | skipping: Conditional result was False
2025-10-08 12:30:30.943492 | 
2025-10-08 12:30:30.943562 | TASK [Ensure legacy workspace directory]
2025-10-08 12:30:31.168080 | controller | changed
2025-10-08 12:30:31.193130 | 
2025-10-08 12:30:31.193222 | PLAY RECAP
2025-10-08 12:30:31.193269 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 12:30:31.193294 | 
2025-10-08 12:30:31.283146 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 12:30:31.283903 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 12:30:32.064616 | 
2025-10-08 12:30:32.067835 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-10-08 12:30:32.112604 | 
2025-10-08 12:30:32.112714 | TASK [Create zuul-output directory]
2025-10-08 12:30:32.601496 | controller | changed
2025-10-08 12:30:32.631088 | 
2025-10-08 12:30:32.631278 | TASK [Slurp Zuul inventory test]
2025-10-08 12:30:33.081508 | controller -> localhost | ok
2025-10-08 12:30:33.088462 | 
2025-10-08 12:30:33.088553 | TASK [Save zuul inventory]
2025-10-08 12:30:33.964100 | controller | changed
2025-10-08 12:30:33.970451 | 
2025-10-08 12:30:33.970523 | TASK [Save zuul vars without the change_message]
2025-10-08 12:30:34.620260 | controller | changed
2025-10-08 12:30:34.665631 | 
2025-10-08 12:30:34.665717 | PLAY RECAP
2025-10-08 12:30:34.665763 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 12:30:34.665788 | 
2025-10-08 12:30:34.811308 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 12:30:34.812069 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 12:30:35.691026 | 
2025-10-08 12:30:35.691160 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-10-08 12:30:35.720121 | 
2025-10-08 12:30:35.720216 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-10-08 12:30:35.753512 | controller | ok
2025-10-08 12:30:35.778489 | 
2025-10-08 12:30:35.778600 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 12:30:35.816578 | controller | skipping: Conditional result was False
2025-10-08 12:30:35.822392 | 
2025-10-08 12:30:35.822538 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 12:30:36.186853 | controller | ok
2025-10-08 12:30:36.193254 | 
2025-10-08 12:30:36.193345 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 12:30:36.802418 | controller | ok
2025-10-08 12:30:36.817485 | 
2025-10-08 12:30:36.817577 | TASK [Prepare workspace]
2025-10-08 12:30:36.848149 | controller | ok
2025-10-08 12:30:36.865802 | 
2025-10-08 12:30:36.865885 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-08 12:30:37.163003 | controller | ok
2025-10-08 12:30:37.171637 | 
2025-10-08 12:30:37.171724 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-08 12:30:40.306820 | controller | Output suppressed because no_log was given
2025-10-08 12:30:40.322146 | 
2025-10-08 12:30:40.322232 | LOOP [Create zuul-output directory]
2025-10-08 12:30:40.530099 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-10-08 12:30:40.691799 | controller | ok: "/home/zuul/zuul-output/logs"
2025-10-08 12:30:40.702427 | 
2025-10-08 12:30:40.702515 | TASK [Install required packages]
2025-10-08 12:31:34.731376 | controller | changed
2025-10-08 12:31:34.736964 | 
2025-10-08 12:31:34.737029 | TASK [Install venv]
2025-10-08 12:32:37.324735 | controller | changed
2025-10-08 12:32:37.351956 | 
2025-10-08 12:32:37.352033 | PLAY RECAP
2025-10-08 12:32:37.352081 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 12:32:37.352106 | 
2025-10-08 12:32:37.454381 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 12:32:37.455242 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 12:32:38.025263 | 
2025-10-08 12:32:38.025369 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-10-08 12:32:38.049244 | 
2025-10-08 12:32:38.049376 | TASK [Gather required facts]
2025-10-08 12:32:38.546007 | controller | ok
2025-10-08 12:32:38.553754 | 
2025-10-08 12:32:38.553887 | TASK [Load environment var if instructed to]
2025-10-08 12:32:38.579486 | controller | skipping: Conditional result was False
2025-10-08 12:32:38.587300 | 
2025-10-08 12:32:38.587379 | TASK [Run molecule]
2025-10-08 12:32:39.563896 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-10-08 12:32:39.632934 | controller | INFO     Performing prerun with role_name_check=0...
2025-10-08 12:32:58.094861 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.095313 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.095812 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.096259 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.096754 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+a7a306bf was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+a7a306bf (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.097196 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.097673 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.098120 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.098607 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.099051 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.099507 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.099949 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.100380 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.100853 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.101288 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 12:32:58.110606 | controller | INFO     Running default > prepare
2025-10-08 12:32:58.790850 | controller |
2025-10-08 12:32:58.790908 | controller | PLAY [Prepare] *****************************************************************
2025-10-08 12:32:58.790939 | controller |
2025-10-08 12:32:58.791057 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:32:58.791163 | controller | Wednesday 08 October 2025  12:32:58 +0000 (0:00:00.020)       0:00:00.020 *****
2025-10-08 12:32:59.600365 | controller | ok: [instance]
2025-10-08 12:32:59.600462 | controller |
2025-10-08 12:32:59.600599 | controller | TASK [Create custom basedir] ***************************************************
2025-10-08 12:32:59.600705 | controller | Wednesday 08 October 2025  12:32:59 +0000 (0:00:00.810)       0:00:00.830 *****
2025-10-08 12:32:59.907398 | controller | ok: [instance]
2025-10-08 12:32:59.907494 | controller |
2025-10-08 12:32:59.907605 | controller | TASK [Install some debug utils] ************************************************
2025-10-08 12:32:59.907714 | controller | Wednesday 08 October 2025  12:32:59 +0000 (0:00:00.306)       0:00:01.137 *****
2025-10-08 12:33:04.414685 | controller | changed: [instance]
2025-10-08 12:33:04.414744 | controller |
2025-10-08 12:33:04.414840 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-10-08 12:33:04.414949 | controller | Wednesday 08 October 2025  12:33:04 +0000 (0:00:04.507)       0:00:05.644 *****
2025-10-08 12:33:04.435016 | controller | skipping: [instance]
2025-10-08 12:33:04.435080 | controller |
2025-10-08 12:33:04.435190 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-10-08 12:33:04.435297 | controller | Wednesday 08 October 2025  12:33:04 +0000 (0:00:00.020)       0:00:05.665 *****
2025-10-08 12:33:04.476040 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-10-08 12:33:04.476125 | controller |
2025-10-08 12:33:04.476249 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-10-08 12:33:04.476356 | controller | Wednesday 08 October 2025  12:33:04 +0000 (0:00:00.040)       0:00:05.706 *****
2025-10-08 12:33:04.757803 | controller | ok: [instance]
2025-10-08 12:33:04.757875 | controller |
2025-10-08 12:33:04.757983 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-10-08 12:33:04.758088 | controller | Wednesday 08 October 2025  12:33:04 +0000 (0:00:00.281)       0:00:05.988 *****
2025-10-08 12:33:04.983151 | controller | ok: [instance]
2025-10-08 12:33:04.983200 | controller |
2025-10-08 12:33:04.983267 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-10-08 12:33:04.983378 | controller | Wednesday 08 October 2025  12:33:04 +0000 (0:00:00.225)       0:00:06.213 *****
2025-10-08 12:33:05.699816 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-10-08 12:33:05.759590 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-10-08 12:33:05.759629 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-10-08 12:33:05.759639 | controller |
2025-10-08 12:33:05.759647 | controller | TASK [Deploy repo-setup] *******************************************************
2025-10-08 12:33:05.759655 | controller | Wednesday 08 October 2025  12:33:05 +0000 (0:00:00.716)       0:00:06.929 *****
2025-10-08 12:33:05.759667 | controller |
2025-10-08 12:33:05.759693 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-10-08 12:33:06.315499 | controller | Wednesday 08 October 2025  12:33:05 +0000 (0:00:00.060)       0:00:06.989 *****
2025-10-08 12:33:06.315551 | controller | changed: [instance] => (item=tmp)
2025-10-08 12:33:06.991842 | controller | changed: [instance] => (item=artifacts/repositories)
2025-10-08 12:33:06.991873 | controller | changed: [instance] => (item=venv/repo_setup)
2025-10-08 12:33:06.991885 | controller |
2025-10-08 12:33:06.991896 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-10-08 12:33:06.991904 | controller | Wednesday 08 October 2025  12:33:06 +0000 (0:00:00.555)       0:00:07.545 *****
2025-10-08 12:33:06.991915 | controller | ok: [instance]
2025-10-08 12:33:08.176102 | controller |
2025-10-08 12:33:08.176139 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-10-08 12:33:08.176148 | controller | Wednesday 08 October 2025  12:33:06 +0000 (0:00:00.676)       0:00:08.221 *****
2025-10-08 12:33:08.176159 | controller | changed: [instance]
2025-10-08 12:33:16.100496 | controller |
2025-10-08 12:33:16.100526 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-10-08 12:33:16.100534 | controller | Wednesday 08 October 2025  12:33:08 +0000 (0:00:01.184)       0:00:09.405 *****
2025-10-08 12:33:16.100546 | controller | changed: [instance]
2025-10-08 12:33:16.814879 | controller |
2025-10-08 12:33:16.814911 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-10-08 12:33:16.814920 | controller | Wednesday 08 October 2025  12:33:16 +0000 (0:00:07.924)       0:00:17.330 *****
2025-10-08 12:33:16.814931 | controller | changed: [instance]
2025-10-08 12:33:16.836198 | controller |
2025-10-08 12:33:16.836221 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-10-08 12:33:16.836229 | controller | Wednesday 08 October 2025  12:33:16 +0000 (0:00:00.714)       0:00:18.044 *****
2025-10-08 12:33:16.836239 | controller | skipping: [instance]
2025-10-08 12:33:17.666513 | controller |
2025-10-08 12:33:17.666541 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-10-08 12:33:17.666550 | controller | Wednesday 08 October 2025  12:33:16 +0000 (0:00:00.021)       0:00:18.066 *****
2025-10-08 12:33:17.666561 | controller | changed: [instance]
2025-10-08 12:33:17.666584 | controller |
2025-10-08 12:33:17.666594 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-10-08 12:33:17.667057 | controller | Wednesday 08 October 2025  12:33:17 +0000 (0:00:00.830)       0:00:18.896 *****
2025-10-08 12:33:17.703324 | controller | skipping: [instance]
2025-10-08 12:33:17.755037 | controller |
2025-10-08 12:33:17.755073 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-10-08 12:33:17.755083 | controller | Wednesday 08 October 2025  12:33:17 +0000 (0:00:00.036)       0:00:18.933 *****
2025-10-08 12:33:17.755096 | controller | skipping: [instance]
2025-10-08 12:33:17.806970 | controller |
2025-10-08 12:33:17.806993 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-10-08 12:33:17.807000 | controller | Wednesday 08 October 2025  12:33:17 +0000 (0:00:00.051)       0:00:18.984 *****
2025-10-08 12:33:17.807010 | controller | skipping: [instance]
2025-10-08 12:33:18.368238 | controller |
2025-10-08 12:33:18.368269 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-10-08 12:33:18.368277 | controller | Wednesday 08 October 2025  12:33:17 +0000 (0:00:00.052)       0:00:19.037 *****
2025-10-08 12:33:18.368288 | controller | changed: [instance]
2025-10-08 12:33:18.801444 | controller |
2025-10-08 12:33:18.801475 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-10-08 12:33:18.801483 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.560)       0:00:19.598 *****
2025-10-08 12:33:18.801498 | controller | changed: [instance]
2025-10-08 12:33:18.831147 | controller |
2025-10-08 12:33:18.831169 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-10-08 12:33:18.831177 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.433)       0:00:20.031 *****
2025-10-08 12:33:18.831188 | controller | skipping: [instance]
2025-10-08 12:33:18.860503 | controller |
2025-10-08 12:33:18.860528 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-10-08 12:33:18.860536 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.029)       0:00:20.061 *****
2025-10-08 12:33:18.860547 | controller | skipping: [instance]
2025-10-08 12:33:18.860760 | controller |
2025-10-08 12:33:18.860774 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-10-08 12:33:18.890780 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.029)       0:00:20.090 *****
2025-10-08 12:33:18.890801 | controller | skipping: [instance]
2025-10-08 12:33:18.929900 | controller |
2025-10-08 12:33:18.929922 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-10-08 12:33:18.929936 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.030)       0:00:20.120 *****
2025-10-08 12:33:18.929955 | controller | ok: [instance]
2025-10-08 12:33:18.957989 | controller |
2025-10-08 12:33:18.958012 | controller | TASK [repo_setup : Create download directory] **********************************
2025-10-08 12:33:18.958019 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.039)       0:00:20.159 *****
2025-10-08 12:33:18.958030 | controller | skipping: [instance]
2025-10-08 12:33:18.985468 | controller |
2025-10-08 12:33:18.985494 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-10-08 12:33:18.985502 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.028)       0:00:20.187 *****
2025-10-08 12:33:18.985512 | controller | skipping: [instance]
2025-10-08 12:33:19.013489 | controller |
2025-10-08 12:33:19.013518 | controller | TASK [Download the RPM] ********************************************************
2025-10-08 12:33:19.013527 | controller | Wednesday 08 October 2025  12:33:18 +0000 (0:00:00.027)       0:00:20.215 *****
2025-10-08 12:33:19.013539 | controller | skipping: [instance]
2025-10-08 12:33:19.013834 | controller |
2025-10-08 12:33:19.013848 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-10-08 12:33:19.040538 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.028)       0:00:20.243 *****
2025-10-08 12:33:19.040582 | controller | skipping: [instance]
2025-10-08 12:33:19.040614 | controller |
2025-10-08 12:33:19.040625 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-10-08 12:33:19.040666 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.027)       0:00:20.270 *****
2025-10-08 12:33:19.069251 | controller | skipping: [instance]
2025-10-08 12:33:19.098315 | controller |
2025-10-08 12:33:19.098336 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-10-08 12:33:19.098343 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.028)       0:00:20.299 *****
2025-10-08 12:33:19.098352 | controller | skipping: [instance]
2025-10-08 12:33:19.125837 | controller |
2025-10-08 12:33:19.125856 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-10-08 12:33:19.125864 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.029)       0:00:20.328 *****
2025-10-08 12:33:19.125873 | controller | skipping: [instance]
2025-10-08 12:33:19.312152 | controller |
2025-10-08 12:33:19.312183 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-10-08 12:33:19.312191 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.027)       0:00:20.355 *****
2025-10-08 12:33:19.312201 | controller | ok: [instance]
2025-10-08 12:33:19.528784 | controller |
2025-10-08 12:33:19.528812 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-10-08 12:33:19.528820 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.186)       0:00:20.541 *****
2025-10-08 12:33:19.528831 | controller | changed: [instance]
2025-10-08 12:33:19.764353 | controller |
2025-10-08 12:33:19.764383 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-10-08 12:33:19.764391 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.216)       0:00:20.758 *****
2025-10-08 12:33:19.764402 | controller | changed: [instance]
2025-10-08 12:33:19.786547 | controller |
2025-10-08 12:33:19.786579 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-10-08 12:33:19.786587 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.235)       0:00:20.994 *****
2025-10-08 12:33:19.786599 | controller | skipping: [instance]
2025-10-08 12:33:19.786618 | controller |
2025-10-08 12:33:19.786629 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-10-08 12:33:19.786658 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.022)       0:00:21.016 *****
2025-10-08 12:33:19.810607 | controller | skipping: [instance]
2025-10-08 12:33:19.810665 | controller |
2025-10-08 12:33:19.810784 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-10-08 12:33:19.810920 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.024)       0:00:21.041 *****
2025-10-08 12:33:19.835664 | controller | skipping: [instance]
2025-10-08 12:33:19.858823 | controller |
2025-10-08 12:33:19.858843 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-10-08 12:33:19.858858 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.024)       0:00:21.065 *****
2025-10-08 12:33:19.858868 | controller | skipping: [instance]
2025-10-08 12:33:19.882726 | controller |
2025-10-08 12:33:19.882749 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-10-08 12:33:19.882756 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.023)       0:00:21.088 *****
2025-10-08 12:33:19.882766 | controller | skipping: [instance]
2025-10-08 12:33:19.906501 | controller |
2025-10-08 12:33:19.906522 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-10-08 12:33:19.906529 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.023)       0:00:21.112 *****
2025-10-08 12:33:19.906539 | controller | skipping: [instance]
2025-10-08 12:33:19.926459 | controller |
2025-10-08 12:33:19.926487 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-10-08 12:33:19.926494 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.023)       0:00:21.136 *****
2025-10-08 12:33:19.926505 | controller | skipping: [instance]
2025-10-08 12:33:19.957482 | controller |
2025-10-08 12:33:19.957502 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-10-08 12:33:19.957510 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.019)       0:00:21.156 *****
2025-10-08 12:33:19.957519 | controller | skipping: [instance]
2025-10-08 12:33:19.957877 | controller |
2025-10-08 12:33:19.976652 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-10-08 12:33:19.976669 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.031)       0:00:21.187 *****
2025-10-08 12:33:19.976679 | controller | skipping: [instance]
2025-10-08 12:33:20.001112 | controller |
2025-10-08 12:33:20.001134 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-10-08 12:33:20.001141 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.018)       0:00:21.206 *****
2025-10-08 12:33:20.001160 | controller | skipping: [instance]
2025-10-08 12:33:20.033078 | controller |
2025-10-08 12:33:20.033099 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-10-08 12:33:20.033108 | controller | Wednesday 08 October 2025  12:33:19 +0000 (0:00:00.024)       0:00:21.231 *****
2025-10-08 12:33:20.033119 | controller | skipping: [instance]
2025-10-08 12:33:20.062483 | controller |
2025-10-08 12:33:20.062502 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-10-08 12:33:20.062510 | controller | Wednesday 08 October 2025  12:33:20 +0000 (0:00:00.031)       0:00:21.263 *****
2025-10-08 12:33:20.062520 | controller | skipping: [instance]
2025-10-08 12:33:20.091929 | controller |
2025-10-08 12:33:20.091961 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-10-08 12:33:20.091971 | controller | Wednesday 08 October 2025  12:33:20 +0000 (0:00:00.029)       0:00:21.292 *****
2025-10-08 12:33:20.091984 | controller | skipping: [instance]
2025-10-08 12:33:20.092054 | controller |
2025-10-08 12:33:20.092178 | controller | TASK [test_deps : Install additional packages] *********************************
2025-10-08 12:33:20.092304 | controller | Wednesday 08 October 2025  12:33:20 +0000 (0:00:00.029)       0:00:21.322 *****
2025-10-08 12:33:20.122079 | controller | skipping: [instance]
2025-10-08 12:34:04.895020 | controller |
2025-10-08 12:34:04.895057 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-10-08 12:34:04.895065 | controller | Wednesday 08 October 2025  12:33:20 +0000 (0:00:00.029)       0:00:21.351 *****
2025-10-08 12:34:04.895077 | controller | ok: [instance]
2025-10-08 12:34:06.039331 | controller |
2025-10-08 12:34:06.039361 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-10-08 12:34:06.039369 | controller | Wednesday 08 October 2025  12:34:04 +0000 (0:00:44.772)       0:01:06.124 *****
2025-10-08 12:34:06.039380 | controller | ok: [instance]
2025-10-08 12:34:06.071536 | controller |
2025-10-08 12:34:06.071576 | controller | TASK [test_deps : Install extra packages] **************************************
2025-10-08 12:34:06.071584 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:01.144)       0:01:07.269 *****
2025-10-08 12:34:06.071598 | controller | skipping: [instance]
2025-10-08 12:34:06.071633 | controller |
2025-10-08 12:34:06.071643 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-10-08 12:34:06.071739 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.032)       0:01:07.301 *****
2025-10-08 12:34:06.273539 | controller | ok: [instance]
2025-10-08 12:34:06.273589 | controller |
2025-10-08 12:34:06.273598 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-10-08 12:34:06.273613 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.201)       0:01:07.503 *****
2025-10-08 12:34:06.458492 | controller | changed: [instance]
2025-10-08 12:34:06.645292 | controller |
2025-10-08 12:34:06.645325 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-10-08 12:34:06.645333 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.184)       0:01:07.688 *****
2025-10-08 12:34:06.645343 | controller | ok: [instance]
2025-10-08 12:34:06.673738 | controller |
2025-10-08 12:34:06.673769 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-10-08 12:34:06.673777 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.186)       0:01:07.875 *****
2025-10-08 12:34:06.673789 | controller | skipping: [instance]
2025-10-08 12:34:06.691118 | controller |
2025-10-08 12:34:06.691150 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-10-08 12:34:06.691158 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.028)       0:01:07.903 *****
2025-10-08 12:34:06.691169 | controller | skipping: [instance]
2025-10-08 12:34:06.711553 | controller |
2025-10-08 12:34:06.711590 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-10-08 12:34:06.711600 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.017)       0:01:07.921 *****
2025-10-08 12:34:06.711613 | controller | ok: [instance]
2025-10-08 12:34:06.739110 | controller |
2025-10-08 12:34:06.739145 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-10-08 12:34:06.739153 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.020)       0:01:07.941 *****
2025-10-08 12:34:06.739165 | controller | skipping: [instance]
2025-10-08 12:35:40.860817 | controller |
2025-10-08 12:35:40.860851 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-10-08 12:35:40.860860 | controller | Wednesday 08 October 2025  12:34:06 +0000 (0:00:00.027)       0:01:07.968 *****
2025-10-08 12:35:40.860871 | controller | changed: [instance]
2025-10-08 12:35:40.860896 | controller |
2025-10-08 12:35:40.860904 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-10-08 12:35:40.860926 | controller | Wednesday 08 October 2025  12:35:40 +0000 (0:01:34.121)       0:02:42.090 *****
2025-10-08 12:35:41.065316 | controller | changed: [instance]
2025-10-08 12:35:41.065390 | controller |
2025-10-08 12:35:41.065548 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-10-08 12:35:41.065656 | controller | Wednesday 08 October 2025  12:35:41 +0000 (0:00:00.204)       0:02:42.295 *****
2025-10-08 12:35:41.444473 | controller | changed: [instance]
2025-10-08 12:35:41.444801 | controller |
2025-10-08 12:35:42.021353 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-10-08 12:35:42.021385 | controller | Wednesday 08 October 2025  12:35:41 +0000 (0:00:00.379)       0:02:42.674 *****
2025-10-08 12:35:42.021398 | controller | changed: [instance]
2025-10-08 12:35:42.021744 | controller |
2025-10-08 12:35:42.216373 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-10-08 12:35:42.216403 | controller | Wednesday 08 October 2025  12:35:42 +0000 (0:00:00.576)       0:02:43.251 *****
2025-10-08 12:35:42.216524 | controller | ok: [instance]
2025-10-08 12:35:42.909882 | controller |
2025-10-08 12:35:42.909915 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-10-08 12:35:42.909923 | controller | Wednesday 08 October 2025  12:35:42 +0000 (0:00:00.194)       0:02:43.446 *****
2025-10-08 12:35:42.909935 | controller | ok: [instance]
2025-10-08 12:35:42.910802 | controller |
2025-10-08 12:35:43.767263 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-10-08 12:35:43.767295 | controller | Wednesday 08 October 2025  12:35:42 +0000 (0:00:00.693)       0:02:44.139 *****
2025-10-08 12:35:43.767316 | controller | changed: [instance]
2025-10-08 12:35:43.845885 | controller |
2025-10-08 12:35:43.845915 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-10-08 12:35:43.845923 | controller | Wednesday 08 October 2025  12:35:43 +0000 (0:00:00.857)       0:02:44.996 *****
2025-10-08 12:35:43.845935 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-10-08 12:35:44.184750 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-10-08 12:35:44.184789 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-10-08 12:35:44.184798 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-10-08 12:35:44.184804 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-10-08 12:35:44.184809 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-10-08 12:35:44.184815 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-10-08 12:35:44.184820 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-10-08 12:35:44.184826 | controller |
2025-10-08 12:35:44.184833 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-10-08 12:35:44.184838 | controller | Wednesday 08 October 2025  12:35:43 +0000 (0:00:00.078)       0:02:45.075 *****
2025-10-08 12:35:44.184851 | controller | changed: [instance]
2025-10-08 12:35:44.184945 | controller |
2025-10-08 12:35:44.184979 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-10-08 12:35:44.517514 | controller | Wednesday 08 October 2025  12:35:44 +0000 (0:00:00.339)       0:02:45.414 *****
2025-10-08 12:35:44.517557 | controller | changed: [instance]
2025-10-08 12:35:44.517621 | controller |
2025-10-08 12:35:44.517632 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-10-08 12:35:44.517770 | controller | Wednesday 08 October 2025  12:35:44 +0000 (0:00:00.332)       0:02:45.747 *****
2025-10-08 12:35:44.852937 | controller | changed: [instance]
2025-10-08 12:35:45.184133 | controller |
2025-10-08 12:35:45.184164 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-10-08 12:35:45.184172 | controller | Wednesday 08 October 2025  12:35:44 +0000 (0:00:00.335)       0:02:46.082 *****
2025-10-08 12:35:45.184183 | controller | changed: [instance]
2025-10-08 12:35:45.184213 | controller |
2025-10-08 12:35:45.184327 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-10-08 12:35:45.184494 | controller | Wednesday 08 October 2025  12:35:45 +0000 (0:00:00.331)       0:02:46.414 *****
2025-10-08 12:35:45.515510 | controller | changed: [instance]
2025-10-08 12:35:45.515598 | controller |
2025-10-08 12:35:45.515865 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-10-08 12:35:45.850090 | controller | Wednesday 08 October 2025  12:35:45 +0000 (0:00:00.331)       0:02:46.745 *****
2025-10-08 12:35:45.850128 | controller | changed: [instance]
2025-10-08 12:35:46.191231 | controller |
2025-10-08 12:35:46.191263 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-10-08 12:35:46.191272 | controller | Wednesday 08 October 2025  12:35:45 +0000 (0:00:00.334)       0:02:47.079 *****
2025-10-08 12:35:46.191283 | controller | changed: [instance]
2025-10-08 12:35:46.526211 | controller |
2025-10-08 12:35:46.526244 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-10-08 12:35:46.526252 | controller | Wednesday 08 October 2025  12:35:46 +0000 (0:00:00.341)       0:02:47.421 *****
2025-10-08 12:35:46.526263 | controller | changed: [instance]
2025-10-08 12:35:46.868017 | controller |
2025-10-08 12:35:46.868058 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-10-08 12:35:46.868067 | controller | Wednesday 08 October 2025  12:35:46 +0000 (0:00:00.334)       0:02:47.755 *****
2025-10-08 12:35:46.868078 | controller | changed: [instance]
2025-10-08 12:35:47.198328 | controller |
2025-10-08 12:35:47.198358 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-10-08 12:35:47.198366 | controller | Wednesday 08 October 2025  12:35:46 +0000 (0:00:00.341)       0:02:48.097 *****
2025-10-08 12:35:47.198377 | controller | changed: [instance]
2025-10-08 12:35:47.528297 | controller |
2025-10-08 12:35:47.528328 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-10-08 12:35:47.528336 | controller | Wednesday 08 October 2025  12:35:47 +0000 (0:00:00.330)       0:02:48.428 *****
2025-10-08 12:35:47.528348 | controller | changed: [instance]
2025-10-08 12:35:47.868429 | controller |
2025-10-08 12:35:47.868483 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-10-08 12:35:47.868492 | controller | Wednesday 08 October 2025  12:35:47 +0000 (0:00:00.329)       0:02:48.758 *****
2025-10-08 12:35:47.868503 | controller | changed: [instance]
2025-10-08 12:35:48.209230 | controller |
2025-10-08 12:35:48.209261 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-10-08 12:35:48.209269 | controller | Wednesday 08 October 2025  12:35:47 +0000 (0:00:00.340)       0:02:49.098 *****
2025-10-08 12:35:48.209280 | controller | changed: [instance]
2025-10-08 12:35:48.536996 | controller |
2025-10-08 12:35:48.537026 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-10-08 12:35:48.537034 | controller | Wednesday 08 October 2025  12:35:48 +0000 (0:00:00.340)       0:02:49.439 *****
2025-10-08 12:35:48.537046 | controller | changed: [instance]
2025-10-08 12:35:48.867910 | controller |
2025-10-08 12:35:48.867941 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-10-08 12:35:48.867949 | controller | Wednesday 08 October 2025  12:35:48 +0000 (0:00:00.327)       0:02:49.766 *****
2025-10-08 12:35:48.867961 | controller | changed: [instance]
2025-10-08 12:35:49.214038 | controller |
2025-10-08 12:35:49.214069 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-10-08 12:35:49.214077 | controller | Wednesday 08 October 2025  12:35:48 +0000 (0:00:00.331)       0:02:50.097 *****
2025-10-08 12:35:49.214088 | controller | changed: [instance]
2025-10-08 12:35:49.544222 | controller |
2025-10-08 12:35:49.544253 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-10-08 12:35:49.544261 | controller | Wednesday 08 October 2025  12:35:49 +0000 (0:00:00.345)       0:02:50.443 *****
2025-10-08 12:35:49.544272 | controller | changed: [instance]
2025-10-08 12:35:49.883513 | controller |
2025-10-08 12:35:49.883543 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-10-08 12:35:49.883558 | controller | Wednesday 08 October 2025  12:35:49 +0000 (0:00:00.330)       0:02:50.774 *****
2025-10-08 12:35:49.883570 | controller | changed: [instance]
2025-10-08 12:35:49.883774 | controller |
2025-10-08 12:35:49.883809 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-10-08 12:35:50.216926 | controller | Wednesday 08 October 2025  12:35:49 +0000 (0:00:00.339)       0:02:51.113 *****
2025-10-08 12:35:50.216963 | controller | changed: [instance]
2025-10-08 12:35:50.553525 | controller |
2025-10-08 12:35:50.553561 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-10-08 12:35:50.553569 | controller | Wednesday 08 October 2025  12:35:50 +0000 (0:00:00.333)       0:02:51.446 *****
2025-10-08 12:35:50.553581 | controller | changed: [instance]
2025-10-08 12:35:50.887560 | controller |
2025-10-08 12:35:50.887604 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-10-08 12:35:50.887614 | controller | Wednesday 08 October 2025  12:35:50 +0000 (0:00:00.336)       0:02:51.783 *****
2025-10-08 12:35:50.887628 | controller | changed: [instance]
2025-10-08 12:35:51.225687 | controller |
2025-10-08 12:35:51.225736 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-10-08 12:35:51.225745 | controller | Wednesday 08 October 2025  12:35:50 +0000 (0:00:00.334)       0:02:52.117 *****
2025-10-08 12:35:51.225768 | controller | changed: [instance]
2025-10-08 12:35:51.225797 | controller |
2025-10-08 12:35:51.225814 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-10-08 12:35:51.225963 | controller | Wednesday 08 October 2025  12:35:51 +0000 (0:00:00.338)       0:02:52.455 *****
2025-10-08 12:35:51.558319 | controller | changed: [instance]
2025-10-08 12:35:51.898720 | controller |
2025-10-08 12:35:51.898752 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-10-08 12:35:51.898760 | controller | Wednesday 08 October 2025  12:35:51 +0000 (0:00:00.332)       0:02:52.788 *****
2025-10-08 12:35:51.898772 | controller | changed: [instance]
2025-10-08 12:35:51.918059 | controller |
2025-10-08 12:35:51.918086 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-10-08 12:35:51.918094 | controller | Wednesday 08 October 2025  12:35:51 +0000 (0:00:00.340)       0:02:53.128 *****
2025-10-08 12:35:51.918105 | controller | skipping: [instance]
2025-10-08 12:35:52.194526 | controller |
2025-10-08 12:35:52.194562 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-10-08 12:35:52.194572 | controller | Wednesday 08 October 2025  12:35:51 +0000 (0:00:00.019)       0:02:53.148 *****
2025-10-08 12:35:52.194587 | controller | ok: [instance]
2025-10-08 12:35:52.194617 | controller |
2025-10-08 12:35:52.194643 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-10-08 12:35:52.194795 | controller | Wednesday 08 October 2025  12:35:52 +0000 (0:00:00.276)       0:02:53.424 *****
2025-10-08 12:35:52.596723 | controller | changed: [instance]
2025-10-08 12:35:52.905877 | controller |
2025-10-08 12:35:52.905908 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-10-08 12:35:52.905917 | controller | Wednesday 08 October 2025  12:35:52 +0000 (0:00:00.401)       0:02:53.826 *****
2025-10-08 12:35:52.905929 | controller | changed: [instance]
2025-10-08 12:35:53.199930 | controller |
2025-10-08 12:35:53.199960 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-10-08 12:35:53.199969 | controller | Wednesday 08 October 2025  12:35:52 +0000 (0:00:00.309)       0:02:54.135 *****
2025-10-08 12:35:53.199980 | controller | [WARNING]: Reset is not implemented for this connection
2025-10-08 12:35:53.224541 | controller | changed: [instance]
2025-10-08 12:35:53.285831 | controller |
2025-10-08 12:35:53.285884 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-10-08 12:35:53.285892 | controller | Wednesday 08 October 2025  12:35:53 +0000 (0:00:00.289)       0:02:54.424 *****
2025-10-08 12:35:53.285898 | controller |
2025-10-08 12:35:53.285904 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:35:53.285909 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-10-08 12:35:53.285915 | controller |
2025-10-08 12:35:53.285921 | controller | Wednesday 08 October 2025  12:35:53 +0000 (0:00:00.026)       0:02:54.451 *****
2025-10-08 12:35:53.285926 | controller | ===============================================================================
2025-10-08 12:35:53.285931 | controller | libvirt_manager : Install packages required for using KVM -------------- 94.12s
2025-10-08 12:35:53.285937 | controller | test_deps : Install selinux python libs -------------------------------- 44.77s
2025-10-08 12:35:53.285942 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.92s
2025-10-08 12:35:53.285963 | controller | Install some debug utils ------------------------------------------------ 4.51s
2025-10-08 12:35:53.285968 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.18s
2025-10-08 12:35:53.285974 | controller | test_deps : Install python yaml libs ------------------------------------ 1.14s
2025-10-08 12:35:53.285979 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.86s
2025-10-08 12:35:53.285985 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.83s
2025-10-08 12:35:53.285990 | controller | Gathering Facts --------------------------------------------------------- 0.81s
2025-10-08 12:35:53.285996 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.72s
2025-10-08 12:35:53.286001 | controller | repo_setup : Install repo-setup package --------------------------------- 0.71s
2025-10-08 12:35:53.286013 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.69s
2025-10-08 12:35:53.286019 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.68s
2025-10-08 12:35:53.286024 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.58s
2025-10-08 12:35:53.286030 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.56s
2025-10-08 12:35:53.286035 | controller | repo_setup : Ensure directories are present ----------------------------- 0.56s
2025-10-08 12:35:53.286040 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.43s
2025-10-08 12:35:53.286045 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.40s
2025-10-08 12:35:53.286051 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.38s
2025-10-08 12:35:53.286057 | controller | libvirt_manager : Ensure read-write socket is enabled for secret. ------- 0.35s
2025-10-08 12:35:53.286070 | controller | INFO     Running default > converge
2025-10-08 12:35:53.720484 | controller |
2025-10-08 12:35:54.498529 | controller | PLAY [Converge] ****************************************************************
2025-10-08 12:35:54.498562 | controller |
2025-10-08 12:35:54.498570 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:35:54.498576 | controller | Wednesday 08 October 2025  12:35:53 +0000 (0:00:00.013)       0:00:00.013 *****
2025-10-08 12:35:54.498588 | controller | ok: [instance]
2025-10-08 12:35:54.498611 | controller |
2025-10-08 12:35:54.498619 | controller | TASK [Crate SSH keypair] *******************************************************
2025-10-08 12:35:54.498735 | controller | Wednesday 08 October 2025  12:35:54 +0000 (0:00:00.778)       0:00:00.792 *****
2025-10-08 12:35:54.866744 | controller | changed: [instance]
2025-10-08 12:35:55.370033 | controller |
2025-10-08 12:35:55.370070 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-10-08 12:35:55.370078 | controller | Wednesday 08 October 2025  12:35:54 +0000 (0:00:00.367)       0:00:01.160 *****
2025-10-08 12:35:55.370090 | controller | changed: [instance]
2025-10-08 12:35:56.332236 | controller |
2025-10-08 12:35:56.332265 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-08 12:35:56.332273 | controller | Wednesday 08 October 2025  12:35:55 +0000 (0:00:00.503)       0:00:01.663 *****
2025-10-08 12:35:56.332285 | controller | changed: [instance]
2025-10-08 12:35:56.371404 | controller |
2025-10-08 12:35:56.371475 | controller | TASK [Discover latest image] ***************************************************
2025-10-08 12:35:56.371485 | controller | Wednesday 08 October 2025  12:35:56 +0000 (0:00:00.962)       0:00:02.625 *****
2025-10-08 12:35:56.371498 | controller |
2025-10-08 12:35:58.097048 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-10-08 12:35:58.097077 | controller | Wednesday 08 October 2025  12:35:56 +0000 (0:00:00.039)       0:00:02.665 *****
2025-10-08 12:35:58.097091 | controller | changed: [instance]
2025-10-08 12:35:58.121839 | controller |
2025-10-08 12:35:58.121869 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-10-08 12:35:58.121884 | controller | Wednesday 08 October 2025  12:35:58 +0000 (0:00:01.725)       0:00:04.390 *****
2025-10-08 12:35:58.121897 | controller | ok: [instance]
2025-10-08 12:36:17.140902 | controller |
2025-10-08 12:36:17.140934 | controller | TASK [Download latest image] ***************************************************
2025-10-08 12:36:17.140943 | controller | Wednesday 08 October 2025  12:35:58 +0000 (0:00:00.024)       0:00:04.415 *****
2025-10-08 12:36:17.140954 | controller | changed: [instance]
2025-10-08 12:36:17.177184 | controller |
2025-10-08 12:36:17.177209 | controller | TASK [Build nat64 appliance image] *********************************************
2025-10-08 12:36:17.177219 | controller | Wednesday 08 October 2025  12:36:17 +0000 (0:00:19.019)       0:00:23.434 *****
2025-10-08 12:36:17.177231 | controller |
2025-10-08 12:36:17.647160 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-10-08 12:36:17.647189 | controller | Wednesday 08 October 2025  12:36:17 +0000 (0:00:00.036)       0:00:23.470 *****
2025-10-08 12:36:17.647209 | controller | ok: [instance] => (item=artifacts)
2025-10-08 12:36:17.849049 | controller | ok: [instance] => (item=logs)
2025-10-08 12:36:17.849080 | controller |
2025-10-08 12:36:17.849088 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-10-08 12:36:17.849094 | controller | Wednesday 08 October 2025  12:36:17 +0000 (0:00:00.469)       0:00:23.940 *****
2025-10-08 12:36:17.849105 | controller | changed: [instance]
2025-10-08 12:36:22.331145 | controller |
2025-10-08 12:36:22.331175 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-10-08 12:36:22.331183 | controller | Wednesday 08 October 2025  12:36:17 +0000 (0:00:00.201)       0:00:24.142 *****
2025-10-08 12:36:22.331194 | controller | ok: [instance]
2025-10-08 12:36:30.478517 | controller |
2025-10-08 12:36:30.478551 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-10-08 12:36:30.478559 | controller | Wednesday 08 October 2025  12:36:22 +0000 (0:00:04.482)       0:00:28.624 *****
2025-10-08 12:36:30.478571 | controller | changed: [instance]
2025-10-08 12:36:40.480537 | controller |
2025-10-08 12:36:40.480569 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-10-08 12:36:40.480578 | controller | Wednesday 08 October 2025  12:36:30 +0000 (0:00:08.147)       0:00:36.772 *****
2025-10-08 12:36:40.480589 | controller | changed: [instance] => (item=elements/)
2025-10-08 12:36:41.677913 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-10-08 12:36:41.677942 | controller |
2025-10-08 12:36:41.677950 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-10-08 12:36:41.677956 | controller | Wednesday 08 October 2025  12:36:40 +0000 (0:00:10.001)       0:00:46.773 *****
2025-10-08 12:36:41.677968 | controller | changed: [instance]
2025-10-08 12:41:12.707465 | controller |
2025-10-08 12:41:12.707711 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-10-08 12:41:12.707723 | controller | Wednesday 08 October 2025  12:36:41 +0000 (0:00:01.197)       0:00:47.971 *****
2025-10-08 12:41:12.707736 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-08 12:41:12.966611 | controller | changed: [instance]
2025-10-08 12:41:12.966647 | controller |
2025-10-08 12:41:12.966655 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-10-08 12:41:12.966661 | controller | Wednesday 08 October 2025  12:41:12 +0000 (0:04:31.028)       0:05:19.000 *****
2025-10-08 12:41:12.966673 | controller | changed: [instance]
2025-10-08 12:41:20.447924 | controller |
2025-10-08 12:41:20.447955 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-10-08 12:41:20.447964 | controller | Wednesday 08 October 2025  12:41:12 +0000 (0:00:00.259)       0:05:19.260 *****
2025-10-08 12:41:20.447976 | controller | changed: [instance]
2025-10-08 12:41:20.498622 | controller |
2025-10-08 12:41:20.498667 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-10-08 12:41:20.498678 | controller | Wednesday 08 October 2025  12:41:20 +0000 (0:00:07.481)       0:05:26.741 *****
2025-10-08 12:41:20.498692 | controller |
2025-10-08 12:41:20.558221 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-10-08 12:41:20.558260 | controller | Wednesday 08 October 2025  12:41:20 +0000 (0:00:00.050)       0:05:26.792 *****
2025-10-08 12:41:20.558275 | controller | ok: [instance]
2025-10-08 12:41:21.430491 | controller |
2025-10-08 12:41:21.430524 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-10-08 12:41:21.430533 | controller | Wednesday 08 October 2025  12:41:20 +0000 (0:00:00.059)       0:05:26.851 *****
2025-10-08 12:41:21.430545 | controller | changed: [instance]
2025-10-08 12:41:21.430908 | controller |
2025-10-08 12:41:21.753040 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-10-08 12:41:21.753072 | controller | Wednesday 08 October 2025  12:41:21 +0000 (0:00:00.872)       0:05:27.723 *****
2025-10-08 12:41:21.753091 | controller | ok: [instance]
2025-10-08 12:41:21.974376 | controller |
2025-10-08 12:41:21.974408 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-10-08 12:41:21.974436 | controller | Wednesday 08 October 2025  12:41:21 +0000 (0:00:00.322)       0:05:28.046 *****
2025-10-08 12:41:21.974455 | controller | ok: [instance]
2025-10-08 12:41:22.195542 | controller |
2025-10-08 12:41:22.195573 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-10-08 12:41:22.195581 | controller | Wednesday 08 October 2025  12:41:21 +0000 (0:00:00.221)       0:05:28.268 *****
2025-10-08 12:41:22.195593 | controller | changed: [instance]
2025-10-08 12:41:22.425038 | controller |
2025-10-08 12:41:22.425108 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-10-08 12:41:22.425120 | controller | Wednesday 08 October 2025  12:41:22 +0000 (0:00:00.221)       0:05:28.489 *****
2025-10-08 12:41:22.425156 | controller | changed: [instance]
2025-10-08 12:41:22.676441 | controller |
2025-10-08 12:41:22.676474 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-10-08 12:41:22.676482 | controller | Wednesday 08 October 2025  12:41:22 +0000 (0:00:00.229)       0:05:28.718 *****
2025-10-08 12:41:22.676495 | controller | ok: [instance]
2025-10-08 12:41:22.904584 | controller |
2025-10-08 12:41:22.904618 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-10-08 12:41:22.904627 | controller | Wednesday 08 October 2025  12:41:22 +0000 (0:00:00.251)       0:05:28.970 *****
2025-10-08 12:41:22.904639 | controller | ok: [instance]
2025-10-08 12:41:23.133846 | controller |
2025-10-08 12:41:23.133879 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-10-08 12:41:23.133888 | controller | Wednesday 08 October 2025  12:41:22 +0000 (0:00:00.228)       0:05:29.198 *****
2025-10-08 12:41:23.133900 | controller | changed: [instance]
2025-10-08 12:41:23.926061 | controller |
2025-10-08 12:41:23.926098 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-10-08 12:41:23.926106 | controller | Wednesday 08 October 2025  12:41:23 +0000 (0:00:00.229)       0:05:29.427 *****
2025-10-08 12:41:23.926118 | controller | changed: [instance] => (item=br-64v6)
2025-10-08 12:41:24.813303 | controller | changed: [instance] => (item=br-64v4)
2025-10-08 12:41:24.813343 | controller |
2025-10-08 12:41:24.813351 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-10-08 12:41:24.813358 | controller | Wednesday 08 October 2025  12:41:23 +0000 (0:00:00.792)       0:05:30.219 *****
2025-10-08 12:41:24.813371 | controller | changed: [instance]
2025-10-08 12:41:24.813395 | controller |
2025-10-08 12:41:24.813403 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-10-08 12:41:24.813578 | controller | Wednesday 08 October 2025  12:41:24 +0000 (0:00:00.887)       0:05:31.107 *****
2025-10-08 12:41:24.844511 | controller | ok: [instance]
2025-10-08 12:41:24.844560 | controller |
2025-10-08 12:41:24.844750 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-10-08 12:41:24.880919 | controller | Wednesday 08 October 2025  12:41:24 +0000 (0:00:00.031)       0:05:31.138 *****
2025-10-08 12:41:24.880957 | controller |
2025-10-08 12:41:25.281797 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-08 12:41:25.281829 | controller | Wednesday 08 October 2025  12:41:24 +0000 (0:00:00.036)       0:05:31.174 *****
2025-10-08 12:41:25.281843 | controller | ok: [instance] => (item=artifacts)
2025-10-08 12:41:26.581355 | controller | ok: [instance] => (item=logs)
2025-10-08 12:41:26.581388 | controller |
2025-10-08 12:41:26.581397 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-08 12:41:26.581403 | controller | Wednesday 08 October 2025  12:41:25 +0000 (0:00:00.400)       0:05:31.575 *****
2025-10-08 12:41:26.581431 | controller | ok: [instance]
2025-10-08 12:41:26.790907 | controller |
2025-10-08 12:41:26.790938 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-08 12:41:26.790947 | controller | Wednesday 08 October 2025  12:41:26 +0000 (0:00:01.299)       0:05:32.874 *****
2025-10-08 12:41:26.790958 | controller | changed: [instance]
2025-10-08 12:41:27.152527 | controller |
2025-10-08 12:41:27.152561 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-08 12:41:27.152570 | controller | Wednesday 08 October 2025  12:41:26 +0000 (0:00:00.209)       0:05:33.084 *****
2025-10-08 12:41:27.152581 | controller | changed: [instance]
2025-10-08 12:41:27.565491 | controller |
2025-10-08 12:41:27.565528 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-08 12:41:27.565537 | controller | Wednesday 08 October 2025  12:41:27 +0000 (0:00:00.361)       0:05:33.446 *****
2025-10-08 12:41:27.565548 | controller | changed: [instance]
2025-10-08 12:41:27.565748 | controller |
2025-10-08 12:41:27.565763 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-08 12:41:27.945177 | controller | Wednesday 08 October 2025  12:41:27 +0000 (0:00:00.413)       0:05:33.859 *****
2025-10-08 12:41:27.945216 | controller | changed: [instance]
2025-10-08 12:41:28.146517 | controller |
2025-10-08 12:41:28.146556 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-08 12:41:28.146565 | controller | Wednesday 08 October 2025  12:41:27 +0000 (0:00:00.379)       0:05:34.238 *****
2025-10-08 12:41:28.146577 | controller | ok: [instance]
2025-10-08 12:41:28.165497 | controller |
2025-10-08 12:41:28.165531 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-08 12:41:28.165541 | controller | Wednesday 08 October 2025  12:41:28 +0000 (0:00:00.201)       0:05:34.439 *****
2025-10-08 12:41:28.165554 | controller | skipping: [instance]
2025-10-08 12:41:28.165799 | controller |
2025-10-08 12:41:28.165816 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-08 12:41:28.403000 | controller | Wednesday 08 October 2025  12:41:28 +0000 (0:00:00.019)       0:05:34.459 *****
2025-10-08 12:41:28.403038 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-08 12:41:29.528443 | controller | changed: [instance]
2025-10-08 12:41:29.528478 | controller |
2025-10-08 12:41:29.528486 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-10-08 12:41:29.528493 | controller | Wednesday 08 October 2025  12:41:28 +0000 (0:00:00.237)       0:05:34.696 *****
2025-10-08 12:41:29.528504 | controller | changed: [instance]
2025-10-08 12:41:30.430499 | controller |
2025-10-08 12:41:30.430530 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-10-08 12:41:30.430538 | controller | Wednesday 08 October 2025  12:41:29 +0000 (0:00:01.125)       0:05:35.821 *****
2025-10-08 12:41:30.430550 | controller | changed: [instance]
2025-10-08 12:41:30.457229 | controller |
2025-10-08 12:41:30.457254 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-10-08 12:41:30.457263 | controller | Wednesday 08 October 2025  12:41:30 +0000 (0:00:00.902)       0:05:36.723 *****
2025-10-08 12:41:30.457274 | controller | ok: [instance]
2025-10-08 12:41:30.501538 | controller |
2025-10-08 12:41:30.501575 | controller | TASK [Set MAC address facts] ***************************************************
2025-10-08 12:41:30.501584 | controller | Wednesday 08 October 2025  12:41:30 +0000 (0:00:00.026)       0:05:36.750 *****
2025-10-08 12:41:30.501598 | controller | ok: [instance]
2025-10-08 12:41:30.754557 | controller |
2025-10-08 12:41:30.754589 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-10-08 12:41:30.754598 | controller | Wednesday 08 October 2025  12:41:30 +0000 (0:00:00.043)       0:05:36.794 *****
2025-10-08 12:41:30.754609 | controller | changed: [instance]
2025-10-08 12:41:31.033030 | controller |
2025-10-08 12:41:31.033064 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-10-08 12:41:31.033072 | controller | Wednesday 08 October 2025  12:41:30 +0000 (0:00:00.253)       0:05:37.048 *****
2025-10-08 12:41:31.033084 | controller | ok: [instance]
2025-10-08 12:41:31.268156 | controller |
2025-10-08 12:41:31.268189 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-10-08 12:41:31.268197 | controller | Wednesday 08 October 2025  12:41:31 +0000 (0:00:00.275)       0:05:37.323 *****
2025-10-08 12:41:31.268209 | controller | ok: [instance]
2025-10-08 12:41:31.509066 | controller |
2025-10-08 12:41:31.509297 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-10-08 12:41:31.509308 | controller | Wednesday 08 October 2025  12:41:31 +0000 (0:00:00.235)       0:05:37.559 *****
2025-10-08 12:41:31.509322 | controller | changed: [instance]
2025-10-08 12:41:31.864038 | controller |
2025-10-08 12:41:31.864075 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-10-08 12:41:31.864094 | controller | Wednesday 08 October 2025  12:41:31 +0000 (0:00:00.240)       0:05:37.799 *****
2025-10-08 12:41:31.864107 | controller | changed: [instance]
2025-10-08 12:41:32.689512 | controller |
2025-10-08 12:41:32.689546 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-08 12:41:32.689554 | controller | Wednesday 08 October 2025  12:41:31 +0000 (0:00:00.357)       0:05:38.157 *****
2025-10-08 12:41:32.689566 | controller | changed: [instance]
2025-10-08 12:41:32.724575 | controller |
2025-10-08 12:41:32.724609 | controller | TASK [Generate test node UUID] *************************************************
2025-10-08 12:41:32.724617 | controller | Wednesday 08 October 2025  12:41:32 +0000 (0:00:00.822)       0:05:38.980 *****
2025-10-08 12:41:32.724629 | controller | ok: [instance]
2025-10-08 12:41:40.688692 | controller |
2025-10-08 12:41:40.688726 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-10-08 12:41:40.688734 | controller | Wednesday 08 October 2025  12:41:32 +0000 (0:00:00.035)       0:05:39.015 *****
2025-10-08 12:41:40.688752 | controller | changed: [instance]
2025-10-08 12:41:40.738737 | controller |
2025-10-08 12:41:40.738781 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-10-08 12:41:40.738789 | controller | Wednesday 08 October 2025  12:41:40 +0000 (0:00:07.966)       0:05:46.982 *****
2025-10-08 12:41:40.738802 | controller |
2025-10-08 12:41:41.266587 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-08 12:41:41.266620 | controller | Wednesday 08 October 2025  12:41:40 +0000 (0:00:00.050)       0:05:47.032 *****
2025-10-08 12:41:41.266634 | controller | ok: [instance] => (item=artifacts)
2025-10-08 12:41:42.693330 | controller | ok: [instance] => (item=logs)
2025-10-08 12:41:42.693363 | controller |
2025-10-08 12:41:42.693371 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-08 12:41:42.693378 | controller | Wednesday 08 October 2025  12:41:41 +0000 (0:00:00.527)       0:05:47.560 *****
2025-10-08 12:41:42.693390 | controller | ok: [instance]
2025-10-08 12:41:42.912481 | controller |
2025-10-08 12:41:42.912515 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-08 12:41:42.912524 | controller | Wednesday 08 October 2025  12:41:42 +0000 (0:00:01.426)       0:05:48.986 *****
2025-10-08 12:41:42.912535 | controller | changed: [instance]
2025-10-08 12:41:43.280504 | controller |
2025-10-08 12:41:43.280544 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-08 12:41:43.280553 | controller | Wednesday 08 October 2025  12:41:42 +0000 (0:00:00.219)       0:05:49.205 *****
2025-10-08 12:41:43.280565 | controller | changed: [instance]
2025-10-08 12:41:43.280585 | controller |
2025-10-08 12:41:43.280677 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-08 12:41:43.280781 | controller | Wednesday 08 October 2025  12:41:43 +0000 (0:00:00.365)       0:05:49.571 *****
2025-10-08 12:41:43.644436 | controller | changed: [instance]
2025-10-08 12:41:43.644493 | controller |
2025-10-08 12:41:43.644610 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-08 12:41:43.644715 | controller | Wednesday 08 October 2025  12:41:43 +0000 (0:00:00.367)       0:05:49.938 *****
2025-10-08 12:41:44.092043 | controller | changed: [instance]
2025-10-08 12:41:44.092095 | controller |
2025-10-08 12:41:44.092218 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-08 12:41:44.092329 | controller | Wednesday 08 October 2025  12:41:44 +0000 (0:00:00.444)       0:05:50.382 *****
2025-10-08 12:41:44.283940 | controller | ok: [instance]
2025-10-08 12:41:44.284000 | controller |
2025-10-08 12:41:44.284123 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-08 12:41:44.284224 | controller | Wednesday 08 October 2025  12:41:44 +0000 (0:00:00.192)       0:05:50.575 *****
2025-10-08 12:41:44.303966 | controller | skipping: [instance]
2025-10-08 12:41:44.304050 | controller |
2025-10-08 12:41:44.304180 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-08 12:41:44.304291 | controller | Wednesday 08 October 2025  12:41:44 +0000 (0:00:00.020)       0:05:50.596 *****
2025-10-08 12:41:44.521499 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-08 12:41:44.521568 | controller | changed: [instance]
2025-10-08 12:41:44.521682 | controller |
2025-10-08 12:41:44.521790 | controller | TASK [Define test-node VM] *****************************************************
2025-10-08 12:41:44.521893 | controller | Wednesday 08 October 2025  12:41:44 +0000 (0:00:00.219)       0:05:50.815 *****
2025-10-08 12:41:44.795628 | controller | changed: [instance]
2025-10-08 12:41:44.795701 | controller |
2025-10-08 12:41:44.795813 | controller | TASK [Start test-node VM] ******************************************************
2025-10-08 12:41:44.795916 | controller | Wednesday 08 October 2025  12:41:44 +0000 (0:00:00.271)       0:05:51.086 *****
2025-10-08 12:41:45.603378 | controller | changed: [instance]
2025-10-08 12:41:45.603456 | controller |
2025-10-08 12:41:45.603567 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-10-08 12:41:45.603669 | controller | Wednesday 08 October 2025  12:41:45 +0000 (0:00:00.808)       0:05:51.895 *****
2025-10-08 12:42:14.354819 | controller | ok: [instance]
2025-10-08 12:42:14.378217 | controller |
2025-10-08 12:42:14.378250 | controller | TASK [Add test node to inventory] **********************************************
2025-10-08 12:42:14.378259 | controller | Wednesday 08 October 2025  12:42:14 +0000 (0:00:28.750)       0:06:20.645 *****
2025-10-08 12:42:14.378270 | controller | changed: [instance]
2025-10-08 12:42:14.378457 | controller |
2025-10-08 12:42:14.378556 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-10-08 12:42:14.378575 | controller | Wednesday 08 October 2025  12:42:14 +0000 (0:00:00.026)       0:06:20.672 *****
2025-10-08 12:42:14.400052 | controller | changed: [instance]
2025-10-08 12:42:34.440486 | controller |
2025-10-08 12:42:34.440516 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-10-08 12:42:34.440535 | controller | Wednesday 08 October 2025  12:42:14 +0000 (0:00:00.021)       0:06:20.693 *****
2025-10-08 12:42:34.440547 | controller | Pausing for 20 seconds
2025-10-08 12:42:40.938501 | controller | ok: [instance]
2025-10-08 12:42:40.938534 | controller |
2025-10-08 12:42:40.938542 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-10-08 12:42:40.938549 | controller | Wednesday 08 October 2025  12:42:34 +0000 (0:00:20.040)       0:06:40.733 *****
2025-10-08 12:42:40.938560 | controller | changed: [instance]
2025-10-08 12:42:40.938916 | controller |
2025-10-08 12:42:42.030609 | controller | TASK [Grab some info from the test node] ***************************************
2025-10-08 12:42:42.030649 | controller | Wednesday 08 October 2025  12:42:40 +0000 (0:00:06.498)       0:06:47.232 *****
2025-10-08 12:42:42.030663 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-08 12:42:43.066076 | controller |
2025-10-08 12:42:43.066116 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-10-08 12:42:43.066125 | controller | Wednesday 08 October 2025  12:42:42 +0000 (0:00:01.091)       0:06:48.324 *****
2025-10-08 12:42:43.066138 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-08 12:42:43.698150 | controller |
2025-10-08 12:42:43.698187 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-10-08 12:42:43.698196 | controller | Wednesday 08 October 2025  12:42:43 +0000 (0:00:01.035)       0:06:49.359 *****
2025-10-08 12:42:43.698208 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-08 12:42:44.214517 | controller |
2025-10-08 12:42:44.214555 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-10-08 12:42:44.214564 | controller | Wednesday 08 October 2025  12:42:43 +0000 (0:00:00.632)       0:06:49.991 *****
2025-10-08 12:42:44.214575 | controller | changed: [instance]
2025-10-08 12:42:44.214599 | controller |
2025-10-08 12:42:44.214607 | controller | TASK [Write test-node info to file] ********************************************
2025-10-08 12:42:44.214726 | controller | Wednesday 08 October 2025  12:42:44 +0000 (0:00:00.516)       0:06:50.508 *****
2025-10-08 12:42:44.568142 | controller | changed: [instance]
2025-10-08 12:42:44.911194 | controller |
2025-10-08 12:42:44.911223 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-10-08 12:42:44.911232 | controller | Wednesday 08 October 2025  12:42:44 +0000 (0:00:00.353)       0:06:50.861 *****
2025-10-08 12:42:44.911243 | controller | changed: [instance]
2025-10-08 12:42:45.252960 | controller |
2025-10-08 12:42:45.252991 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-10-08 12:42:45.252999 | controller | Wednesday 08 October 2025  12:42:44 +0000 (0:00:00.343)       0:06:51.204 *****
2025-10-08 12:42:45.253010 | controller | changed: [instance]
2025-10-08 12:42:45.580104 | controller |
2025-10-08 12:42:45.580136 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-10-08 12:42:45.580145 | controller | Wednesday 08 October 2025  12:42:45 +0000 (0:00:00.341)       0:06:51.546 *****
2025-10-08 12:42:45.580156 | controller | changed: [instance]
2025-10-08 12:42:45.580179 | controller |
2025-10-08 12:42:45.580187 | controller | TASK [Write hypervisor info to file] *******************************************
2025-10-08 12:42:45.580265 | controller | Wednesday 08 October 2025  12:42:45 +0000 (0:00:00.327)       0:06:51.873 *****
2025-10-08 12:42:45.911984 | controller | changed: [instance]
2025-10-08 12:42:47.543043 | controller |
2025-10-08 12:42:47.543089 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-10-08 12:42:47.543098 | controller | Wednesday 08 October 2025  12:42:45 +0000 (0:00:00.331)       0:06:52.205 *****
2025-10-08 12:42:47.543109 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-08 12:42:47.581958 | controller |
2025-10-08 12:42:47.581989 | controller | TASK [Debug the ping example.com result] ***************************************
2025-10-08 12:42:47.581997 | controller | Wednesday 08 October 2025  12:42:47 +0000 (0:00:01.630)       0:06:53.836 *****
2025-10-08 12:42:47.582008 | controller | ok: [instance] => (item=0) =>
2025-10-08 12:42:47.582041 | controller |   msg: '0'
2025-10-08 12:42:47.582548 | 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=40.7 ms', '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=40.2 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 40.204/40.444/40.685/0.240 ms']) =>
2025-10-08 12:42:47.582603 | controller |   msg:
2025-10-08 12:42:47.582612 | controller |   - PING example.com(a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450)) 56 data bytes
2025-10-08 12:42:47.582621 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=1 ttl=47 time=40.7 ms'
2025-10-08 12:42:47.583467 | controller |   - '64 bytes from a23-192-228-80.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17c0:e450): icmp_seq=2 ttl=47 time=40.2 ms'
2025-10-08 12:42:47.585818 | controller |   - ''
2025-10-08 12:42:47.585840 | controller |   - '--- example.com ping statistics ---'
2025-10-08 12:42:47.585849 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-10-08 12:42:47.585855 | controller |   - rtt min/avg/max/mdev = 40.204/40.444/40.685/0.240 ms
2025-10-08 12:42:47.585861 | controller | ok: [instance] => (item=[]) =>
2025-10-08 12:42:47.585867 | controller |   msg: []
2025-10-08 12:42:47.585873 | controller |
2025-10-08 12:42:47.585879 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:42:47.585889 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-10-08 12:42:47.648435 | controller |
2025-10-08 12:42:47.648470 | controller | Wednesday 08 October 2025  12:42:47 +0000 (0:00:00.039)       0:06:53.875 *****
2025-10-08 12:42:47.648480 | controller | ===============================================================================
2025-10-08 12:42:47.648486 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 271.03s
2025-10-08 12:42:47.648491 | controller | Wait for test node to be reachable via ssh ----------------------------- 28.75s
2025-10-08 12:42:47.648497 | controller | Wait a little to let the test instance boot. --------------------------- 20.04s
2025-10-08 12:42:47.648508 | controller | Download latest image -------------------------------------------------- 19.02s
2025-10-08 12:42:47.648514 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir -------------- 10.00s
2025-10-08 12:42:47.648526 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.15s
2025-10-08 12:42:47.648531 | controller | Make an a copy of the discovered/downloaded image ----------------------- 7.97s
2025-10-08 12:42:47.648537 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.48s
2025-10-08 12:42:47.648542 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.50s
2025-10-08 12:42:47.648548 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.48s
2025-10-08 12:42:47.648553 | controller | discover_latest_image : Get latest image -------------------------------- 1.73s
2025-10-08 12:42:47.648558 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.63s
2025-10-08 12:42:47.648564 | controller | config_drive : Install required RPM packages ---------------------------- 1.43s
2025-10-08 12:42:47.648569 | controller | config_drive : Install required RPM packages ---------------------------- 1.30s
2025-10-08 12:42:47.648575 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.20s
2025-10-08 12:42:47.648581 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.13s
2025-10-08 12:42:47.648586 | controller | Grab some info from the test node --------------------------------------- 1.09s
2025-10-08 12:42:47.648591 | controller | Grab some info from the nat64 appliance --------------------------------- 1.04s
2025-10-08 12:42:47.648597 | controller | Restart firewalld.service ----------------------------------------------- 0.96s
2025-10-08 12:42:47.648602 | controller | nat64_appliance : Start nat64-appliance VM ------------------------------ 0.90s
2025-10-08 12:42:47.648614 | controller | INFO     Running default > cleanup
2025-10-08 12:42:48.115521 | controller |
2025-10-08 12:42:48.115579 | controller | PLAY [Cleanup] *****************************************************************
2025-10-08 12:42:48.115595 | controller |
2025-10-08 12:42:48.115603 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 12:42:48.115612 | controller | Wednesday 08 October 2025  12:42:48 +0000 (0:00:00.050)       0:00:00.050 *****
2025-10-08 12:42:49.014571 | controller | ok: [instance]
2025-10-08 12:42:49.014775 | controller |
2025-10-08 12:42:49.014795 | controller | TASK [Destroy the test-node] ***************************************************
2025-10-08 12:42:49.559936 | controller | Wednesday 08 October 2025  12:42:49 +0000 (0:00:00.899)       0:00:00.950 *****
2025-10-08 12:42:49.559973 | controller | ok: [instance]
2025-10-08 12:42:49.780218 | controller |
2025-10-08 12:42:49.780251 | controller | TASK [Undefine the test-node] **************************************************
2025-10-08 12:42:49.780259 | controller | Wednesday 08 October 2025  12:42:49 +0000 (0:00:00.545)       0:00:01.495 *****
2025-10-08 12:42:49.780271 | controller | ok: [instance]
2025-10-08 12:42:50.141048 | controller |
2025-10-08 12:42:50.141093 | controller | TASK [Destroy the test network] ************************************************
2025-10-08 12:42:50.141101 | controller | Wednesday 08 October 2025  12:42:49 +0000 (0:00:00.220)       0:00:01.715 *****
2025-10-08 12:42:50.141113 | controller | ok: [instance]
2025-10-08 12:42:50.355168 | controller |
2025-10-08 12:42:50.355199 | controller | TASK [Undefine the test network] ***********************************************
2025-10-08 12:42:50.355207 | controller | Wednesday 08 October 2025  12:42:50 +0000 (0:00:00.360)       0:00:02.076 *****
2025-10-08 12:42:50.355219 | controller | ok: [instance]
2025-10-08 12:42:50.385479 | controller |
2025-10-08 12:42:50.385507 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-10-08 12:42:50.385517 | controller | Wednesday 08 October 2025  12:42:50 +0000 (0:00:00.214)       0:00:02.290 *****
2025-10-08 12:42:50.385529 | controller |
2025-10-08 12:42:50.385766 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-10-08 12:42:50.687906 | controller | Wednesday 08 October 2025  12:42:50 +0000 (0:00:00.030)       0:00:02.321 *****
2025-10-08 12:42:50.687942 | controller | changed: [instance]
2025-10-08 12:42:50.967542 | controller |
2025-10-08 12:42:50.967574 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-10-08 12:42:50.967583 | controller | Wednesday 08 October 2025  12:42:50 +0000 (0:00:00.301)       0:00:02.623 *****
2025-10-08 12:42:50.967599 | controller | ok: [instance]
2025-10-08 12:42:50.967882 | controller |
2025-10-08 12:42:50.967897 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-10-08 12:42:51.196186 | controller | Wednesday 08 October 2025  12:42:50 +0000 (0:00:00.279)       0:00:02.902 *****
2025-10-08 12:42:51.196226 | controller | ok: [instance]
2025-10-08 12:42:51.858075 | controller |
2025-10-08 12:42:51.858109 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-10-08 12:42:51.858118 | controller | Wednesday 08 October 2025  12:42:51 +0000 (0:00:00.228)       0:00:03.131 *****
2025-10-08 12:42:51.858130 | controller | ok: [instance]
2025-10-08 12:42:52.110696 | controller |
2025-10-08 12:42:52.110731 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-10-08 12:42:52.110740 | controller | Wednesday 08 October 2025  12:42:51 +0000 (0:00:00.661)       0:00:03.792 *****
2025-10-08 12:42:52.110752 | controller | ok: [instance]
2025-10-08 12:42:52.894990 | controller |
2025-10-08 12:42:52.895035 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-10-08 12:42:52.895045 | controller | Wednesday 08 October 2025  12:42:52 +0000 (0:00:00.252)       0:00:04.045 *****
2025-10-08 12:42:52.895075 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-08 12:42:53.362062 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-08 12:42:53.362096 | controller |
2025-10-08 12:42:53.362104 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-10-08 12:42:53.362111 | controller | Wednesday 08 October 2025  12:42:52 +0000 (0:00:00.784)       0:00:04.830 *****
2025-10-08 12:42:53.362122 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-08 12:42:53.412204 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-08 12:42:53.412238 | controller |
2025-10-08 12:42:53.412247 | controller | PLAY RECAP *********************************************************************
2025-10-08 12:42:53.412253 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-10-08 12:42:53.412259 | controller |
2025-10-08 12:42:53.412265 | controller | Wednesday 08 October 2025  12:42:53 +0000 (0:00:00.465)       0:00:05.295 *****
2025-10-08 12:42:53.412271 | controller | ===============================================================================
2025-10-08 12:42:53.412277 | controller | Gathering Facts --------------------------------------------------------- 0.90s
2025-10-08 12:42:53.412282 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.78s
2025-10-08 12:42:53.412288 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.66s
2025-10-08 12:42:53.412293 | controller | Destroy the test-node --------------------------------------------------- 0.55s
2025-10-08 12:42:53.412299 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.47s
2025-10-08 12:42:53.412304 | controller | Destroy the test network ------------------------------------------------ 0.36s
2025-10-08 12:42:53.412310 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.30s
2025-10-08 12:42:53.412316 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.28s
2025-10-08 12:42:53.412321 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.25s
2025-10-08 12:42:53.412326 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.23s
2025-10-08 12:42:53.412332 | controller | Undefine the test-node -------------------------------------------------- 0.22s
2025-10-08 12:42:53.412337 | controller | Undefine the test network ----------------------------------------------- 0.21s
2025-10-08 12:42:53.412343 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-10-08 12:42:53.412354 | controller | INFO     Writing /tmp/report.html report.
2025-10-08 12:42:53.835096 | [controller] Waiting on logger
2025-10-08 12:42:58.994291 | [controller] Waiting on logger
2025-10-08 12:43:09.427379 | [controller] Waiting on logger
2025-10-08 12:43:19.859421 | [controller] Waiting on logger
2025-10-08 12:43:23.496181 | [Zuul] Log Stream did not terminate
2025-10-08 12:43:23.496393 | controller | changed
2025-10-08 12:43:23.520997 | 
2025-10-08 12:43:23.521068 | PLAY RECAP
2025-10-08 12:43:23.521111 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 12:43:23.521135 | 
2025-10-08 12:43:23.600993 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 12:43:23.601800 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 12:43:24.193717 | 
2025-10-08 12:43:24.193829 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-10-08 12:43:24.215785 | 
2025-10-08 12:43:24.215893 | TASK [Filter out host if needed]
2025-10-08 12:43:24.224991 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-10-08 12:43:24.229862 | 
2025-10-08 12:43:24.229964 | TASK [Ensure file is present]
2025-10-08 12:43:24.573539 | controller | ok
2025-10-08 12:43:24.580453 | 
2025-10-08 12:43:24.580532 | TASK [Manage molecule report file]
2025-10-08 12:43:24.602480 | [controller] Waiting on logger
2025-10-08 12:43:33.975839 | [controller] Waiting on logger
2025-10-08 12:43:44.370366 | [controller] Waiting on logger
2025-10-08 12:43:54.802591 | [controller] Waiting on logger
2025-10-08 12:43:54.935611 | [Zuul] Log Stream did not terminate
2025-10-08 12:43:54.935801 | controller | changed
2025-10-08 12:43:54.941441 | 
2025-10-08 12:43:54.941526 | TASK [Check if we get ci-framework-data basedir]
2025-10-08 12:43:55.145439 | controller | ok
2025-10-08 12:43:55.150530 | 
2025-10-08 12:43:55.150620 | TASK [Create ci-framework-data log directory for zuul]
2025-10-08 12:43:55.475415 | controller | changed
2025-10-08 12:43:55.481234 | 
2025-10-08 12:43:55.481302 | TASK [Copy ci-framework interesting files]
2025-10-08 12:44:00.509996 | controller | changed
2025-10-08 12:44:00.515417 | 
2025-10-08 12:44:00.515484 | TASK [Get SELinux listing]
2025-10-08 12:44:00.535962 | [controller] Waiting on logger
2025-10-08 12:44:08.242301 | [controller] Waiting on logger
2025-10-08 12:44:20.210286 | [controller] Waiting on logger
2025-10-08 12:44:26.903099 | [controller] Waiting on logger
2025-10-08 12:44:29.669331 | controller | changed
2025-10-08 12:44:29.676389 | 
2025-10-08 12:44:29.676481 | TASK [Generate log index]
2025-10-08 12:44:30.469605 | controller | changed
2025-10-08 12:44:30.484239 | 
2025-10-08 12:44:30.484340 | TASK [Get some env related data]
2025-10-08 12:44:33.586346 | [controller] Waiting on logger
2025-10-08 12:44:42.967015 | [controller] Waiting on logger
2025-10-08 12:44:53.362353 | [controller] Waiting on logger
2025-10-08 12:45:01.885323 | [Zuul] Log Stream did not terminate
2025-10-08 12:45:01.885487 | controller | changed
2025-10-08 12:45:01.891254 | 
2025-10-08 12:45:01.891367 | TASK [Generate list of logs to collect in home directory]
2025-10-08 12:45:02.196777 | controller | ok: All paths examined
2025-10-08 12:45:02.202595 | 
2025-10-08 12:45:02.202715 | LOOP [Copy logs from home directory]
2025-10-08 12:45:02.523648 | controller | changed:
2025-10-08 12:45:02.523800 | controller | {
2025-10-08 12:45:02.523836 | controller |   "atime": 1759926739.364823,
2025-10-08 12:45:02.523858 | controller |   "ctime": 1759926756.8989642,
2025-10-08 12:45:02.523875 | controller |   "dev": 64513,
2025-10-08 12:45:02.523921 | controller |   "gid": 1000,
2025-10-08 12:45:02.523951 | controller |   "gr_name": "zuul",
2025-10-08 12:45:02.523970 | controller |   "inode": 4451390,
2025-10-08 12:45:02.523993 | controller |   "isblk": false,
2025-10-08 12:45:02.524010 | controller |   "ischr": false,
2025-10-08 12:45:02.524028 | controller |   "isdir": false,
2025-10-08 12:45:02.524044 | controller |   "isfifo": false,
2025-10-08 12:45:02.524060 | controller |   "isgid": false,
2025-10-08 12:45:02.524075 | controller |   "islnk": false,
2025-10-08 12:45:02.524090 | controller |   "isreg": true,
2025-10-08 12:45:02.524104 | controller |   "issock": false,
2025-10-08 12:45:02.524118 | controller |   "isuid": false,
2025-10-08 12:45:02.524132 | controller |   "mode": "0644",
2025-10-08 12:45:02.524148 | controller |   "mtime": 1759926756.8989642,
2025-10-08 12:45:02.524163 | controller |   "nlink": 1,
2025-10-08 12:45:02.524176 | controller |   "path": "/home/zuul/ansible.log",
2025-10-08 12:45:02.524190 | controller |   "pw_name": "zuul",
2025-10-08 12:45:02.524204 | controller |   "rgrp": true,
2025-10-08 12:45:02.524217 | controller |   "roth": true,
2025-10-08 12:45:02.524230 | controller |   "rusr": true,
2025-10-08 12:45:02.524243 | controller |   "size": 6749,
2025-10-08 12:45:02.524256 | controller |   "uid": 1000,
2025-10-08 12:45:02.524270 | controller |   "wgrp": false,
2025-10-08 12:45:02.524284 | controller |   "woth": false,
2025-10-08 12:45:02.524297 | controller |   "wusr": true,
2025-10-08 12:45:02.524311 | controller |   "xgrp": false,
2025-10-08 12:45:02.524324 | controller |   "xoth": false,
2025-10-08 12:45:02.524337 | controller |   "xusr": false
2025-10-08 12:45:02.524350 | controller | }
2025-10-08 12:45:02.532886 | 
2025-10-08 12:45:02.532980 | TASK [Copy crio stats log file]
2025-10-08 12:45:02.546727 | controller | skipping: Conditional result was False
2025-10-08 12:45:02.553099 | 
2025-10-08 12:45:02.553179 | TASK [Get SELinux related data]
2025-10-08 12:45:02.576879 | [controller] Waiting on logger
2025-10-08 12:45:05.843420 | [controller] Waiting on logger
2025-10-08 12:45:22.290631 | [controller] Waiting on logger
2025-10-08 12:45:25.554371 | [controller] Waiting on logger
2025-10-08 12:45:32.788640 | [Zuul] Log Stream did not terminate
2025-10-08 12:45:32.788834 | controller | ERROR
2025-10-08 12:45:32.788973 | controller | {
2025-10-08 12:45:32.789014 | controller |   "delta": "0:00:00.008468",
2025-10-08 12:45:32.789039 | controller |   "end": "2025-10-08 12:45:02.763185",
2025-10-08 12:45:32.789059 | controller |   "msg": "non-zero return code",
2025-10-08 12:45:32.789077 | controller |   "rc": 1,
2025-10-08 12:45:32.789095 | controller |   "start": "2025-10-08 12:45:02.754717"
2025-10-08 12:45:32.789112 | controller | }
2025-10-08 12:45:32.789137 | controller | ERROR: Ignoring Errors
2025-10-08 12:45:32.794480 | 
2025-10-08 12:45:32.794548 | TASK [Create system configuration directory]
2025-10-08 12:45:33.010951 | controller | changed
2025-10-08 12:45:33.017317 | 
2025-10-08 12:45:33.017401 | TASK [Get some of the system configurations]
2025-10-08 12:45:33.062204 | [controller] Waiting on logger
2025-10-08 12:45:43.474323 | [controller] Waiting on logger
2025-10-08 12:45:52.855039 | [controller] Waiting on logger
2025-10-08 12:46:03.250287 | [controller] Waiting on logger
2025-10-08 12:46:03.321364 | [Zuul] Log Stream did not terminate
2025-10-08 12:46:03.321508 | controller | changed
2025-10-08 12:46:03.326676 | 
2025-10-08 12:46:03.326743 | TASK [Copy generated documentation if available]
2025-10-08 12:46:03.341274 | controller | skipping: Conditional result was False
2025-10-08 12:46:03.347620 | 
2025-10-08 12:46:03.347708 | TASK [Copy generated AsciiDoc documentation if available]
2025-10-08 12:46:03.375581 | controller | skipping: Conditional result was False
2025-10-08 12:46:03.383173 | 
2025-10-08 12:46:03.383266 | TASK [Compress logs bigger than 2MB]
2025-10-08 12:46:06.515321 | [controller] Waiting on logger
2025-10-08 12:46:18.994356 | [controller] Waiting on logger
2025-10-08 12:46:29.426350 | [controller] Waiting on logger
2025-10-08 12:46:33.623767 | [Zuul] Log Stream did not terminate
2025-10-08 12:46:33.623961 | controller | changed
2025-10-08 12:46:33.629263 | 
2025-10-08 12:46:33.629332 | TASK [Copy files from workspace on node]
2025-10-08 12:46:33.647659 | controller | ok
2025-10-08 12:46:33.670313 | 
2025-10-08 12:46:33.670420 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 12:46:33.685534 | controller | skipping: Conditional result was False
2025-10-08 12:46:33.692121 | 
2025-10-08 12:46:33.692204 | TASK [fetch-output : Set log path for single node]
2025-10-08 12:46:33.721875 | controller | ok
2025-10-08 12:46:33.726717 | 
2025-10-08 12:46:33.726783 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 12:46:33.928166 | controller -> localhost | ok: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/logs"
2025-10-08 12:46:33.928418 | controller -> localhost | changed: All items complete
2025-10-08 12:46:33.928464 | 
2025-10-08 12:46:34.129151 | controller -> localhost | changed: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/artifacts"
2025-10-08 12:46:34.326445 | controller -> localhost | changed: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/docs"
2025-10-08 12:46:34.338269 | 
2025-10-08 12:46:34.338350 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 12:46:34.928334 | controller | changed:
2025-10-08 12:46:34.928562 | controller | .d..t...... ./
2025-10-08 12:46:34.928599 | controller | >f+++++++++ README.html
2025-10-08 12:46:34.928624 | controller | >f+++++++++ ansible-execution.log
2025-10-08 12:46:34.928647 | controller | >f+++++++++ ansible.log
2025-10-08 12:46:34.928667 | controller | >f+++++++++ dmesg.log
2025-10-08 12:46:34.928686 | controller | >f+++++++++ installed-pkgs.log
2025-10-08 12:46:34.928704 | controller | >f+++++++++ python.log
2025-10-08 12:46:34.928720 | controller | >f+++++++++ registries.conf
2025-10-08 12:46:34.928738 | controller | >f+++++++++ report.html
2025-10-08 12:46:34.928754 | controller | >f+++++++++ selinux-denials.log
2025-10-08 12:46:34.928771 | controller | >f+++++++++ selinux-listing.log
2025-10-08 12:46:34.928787 | controller | cd+++++++++ ci-framework-data/
2025-10-08 12:46:34.928803 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-10-08 12:46:34.928819 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-10-08 12:46:34.928836 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-10-08 12:46:34.928853 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-10-08 12:46:34.928870 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-10-08 12:46:34.928886 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-10-08 12:46:34.928902 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c7000f8c-16ab-5199-ac46-56ada47a43aa/
2025-10-08 12:46:34.928978 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c7000f8c-16ab-5199-ac46-56ada47a43aa/meta-data
2025-10-08 12:46:34.929003 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c7000f8c-16ab-5199-ac46-56ada47a43aa/network-config
2025-10-08 12:46:34.929022 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c7000f8c-16ab-5199-ac46-56ada47a43aa/user-data
2025-10-08 12:46:34.929040 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f86eaebb-8c32-5a64-bbc4-1c2c1d59e1ed/
2025-10-08 12:46:34.929057 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f86eaebb-8c32-5a64-bbc4-1c2c1d59e1ed/meta-data
2025-10-08 12:46:34.929074 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f86eaebb-8c32-5a64-bbc4-1c2c1d59e1ed/network-config
2025-10-08 12:46:34.929090 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/f86eaebb-8c32-5a64-bbc4-1c2c1d59e1ed/user-data
2025-10-08 12:46:34.929107 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-10-08 12:46:34.929125 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-10-08 12:46:34.929148 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-10-08 12:46:34.929168 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-10-08 12:46:34.929186 | controller | cd+++++++++ ci-framework-data/logs/
2025-10-08 12:46:34.929204 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-08 12:46:34.929222 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-08 12:46:34.929239 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-08 12:46:34.929256 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-10-08 12:46:34.929272 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-10-08 12:46:34.929288 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-10-08 12:46:34.929304 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-10-08 12:46:34.929320 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-10-08 12:46:34.929335 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-10-08 12:46:34.929351 | controller | cd+++++++++ registries.conf.d/
2025-10-08 12:46:34.929367 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-10-08 12:46:34.929382 | controller | cd+++++++++ system-config/
2025-10-08 12:46:34.929397 | controller | cd+++++++++ system-config/libvirt/
2025-10-08 12:46:34.929413 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-10-08 12:46:34.929429 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-10-08 12:46:34.929445 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-10-08 12:46:34.929460 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-10-08 12:46:34.929475 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-10-08 12:46:34.929492 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-10-08 12:46:34.929508 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-10-08 12:46:34.929524 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-10-08 12:46:34.929541 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-10-08 12:46:34.929556 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-10-08 12:46:34.929572 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-10-08 12:46:34.929587 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-10-08 12:46:34.929601 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-10-08 12:46:34.929616 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-10-08 12:46:34.929631 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-10-08 12:46:34.929647 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-10-08 12:46:35.316858 | controller | changed: .d..t...... ./
2025-10-08 12:46:35.709249 | controller | changed: .d..t...... ./
2025-10-08 12:46:35.730903 | 
2025-10-08 12:46:35.731032 | TASK [Return artifact to Zuul]
2025-10-08 12:46:35.760203 | controller | ok
2025-10-08 12:46:35.780353 | 
2025-10-08 12:46:35.780433 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-10-08 12:46:35.780532 | 
2025-10-08 12:46:35.780560 | PLAY RECAP
2025-10-08 12:46:35.780598 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-10-08 12:46:35.780619 | 
2025-10-08 12:46:35.881247 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 12:46:35.882160 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 12:46:36.466019 | 
2025-10-08 12:46:36.466121 | PLAY [all]
2025-10-08 12:46:36.485085 | 
2025-10-08 12:46:36.485315 | TASK [include_role : fetch-output]
2025-10-08 12:46:36.523964 | controller | ok
2025-10-08 12:46:36.542227 | 
2025-10-08 12:46:36.542336 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 12:46:36.586414 | controller | skipping: Conditional result was False
2025-10-08 12:46:36.592635 | 
2025-10-08 12:46:36.592726 | TASK [fetch-output : Set log path for single node]
2025-10-08 12:46:36.621367 | controller | ok
2025-10-08 12:46:36.626671 | 
2025-10-08 12:46:36.626754 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 12:46:36.994409 | controller -> localhost | ok: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/logs"
2025-10-08 12:46:37.186272 | controller -> localhost | ok: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/artifacts"
2025-10-08 12:46:37.386389 | controller -> localhost | ok: "/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/docs"
2025-10-08 12:46:37.398968 | 
2025-10-08 12:46:37.399057 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 12:46:37.937277 | controller | ok
2025-10-08 12:46:37.937501 | controller | ok: All items complete
2025-10-08 12:46:37.937537 | 
2025-10-08 12:46:38.340206 | controller | ok
2025-10-08 12:46:38.727036 | controller | ok
2025-10-08 12:46:38.745382 | 
2025-10-08 12:46:38.745520 | TASK [include_role : fetch-output-openshift]
2025-10-08 12:46:38.759197 | controller | skipping: Conditional result was False
2025-10-08 12:46:38.765102 | 
2025-10-08 12:46:38.765256 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-08 12:46:39.133046 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006262
2025-10-08 12:46:39.345869 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.013503
2025-10-08 12:46:39.382790 | 
2025-10-08 12:46:39.382964 | PLAY [all]
2025-10-08 12:46:39.397364 | 
2025-10-08 12:46:39.397435 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-08 12:46:39.801630 | controller | changed
2025-10-08 12:46:39.825023 | 
2025-10-08 12:46:39.825104 | PLAY RECAP
2025-10-08 12:46:39.825150 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-08 12:46:39.825172 | 
2025-10-08 12:46:39.901493 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 12:46:39.902246 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-08 12:46:40.514234 | 
2025-10-08 12:46:40.514420 | PLAY [localhost]
2025-10-08 12:46:40.531530 | 
2025-10-08 12:46:40.531615 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-08 12:46:40.895307 | localhost | changed
2025-10-08 12:46:40.899705 | 
2025-10-08 12:46:40.899939 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-08 12:46:40.917618 | localhost | ok
2025-10-08 12:46:40.926100 | 
2025-10-08 12:46:40.926174 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-08 12:46:41.249536 | localhost | changed
2025-10-08 12:46:41.255473 | 
2025-10-08 12:46:41.255574 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-08 12:46:41.851147 | localhost | changed
2025-10-08 12:46:41.856029 | 
2025-10-08 12:46:41.856200 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-08 12:46:42.218081 | localhost | Identity added: /var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/tmp/ansible.31guuiwz (/var/lib/zuul/builds/d71e3a06924c4080afcba226bfb0e709/work/tmp/ansible.31guuiwz)
2025-10-08 12:46:42.218249 | localhost | ok: Runtime: 0:00:00.006663
2025-10-08 12:46:42.222556 | 
2025-10-08 12:46:42.222629 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-08 12:46:42.454355 | localhost | ok: Runtime: 0:00:00.004467
2025-10-08 12:46:42.459287 | 
2025-10-08 12:46:42.459376 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-08 12:46:42.508335 | localhost | changed
2025-10-08 12:46:42.512569 | 
2025-10-08 12:46:42.512654 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-08 12:46:42.854732 | localhost | changed
2025-10-08 12:46:42.890484 | 
2025-10-08 12:46:42.890563 | PLAY [localhost]
2025-10-08 12:46:42.902134 | 
2025-10-08 12:46:42.902205 | TASK [Generate bulk log download script]
2025-10-08 12:46:42.920506 | localhost | ok
2025-10-08 12:46:42.932836 | 
2025-10-08 12:46:42.932945 | TASK [local-log-download : Check API endpoint is defined]
2025-10-08 12:46:42.960580 | localhost | ok: All assertions passed
2025-10-08 12:46:42.965076 | 
2025-10-08 12:46:42.965155 | TASK [local-log-download : Create download script]
2025-10-08 12:46:43.353603 | localhost -> localhost | changed
2025-10-08 12:46:43.363959 | 
2025-10-08 12:46:43.364054 | TASK [Register quick-download link]
2025-10-08 12:46:43.382372 | localhost | ok
2025-10-08 12:46:43.430174 | 
2025-10-08 12:46:43.430261 | PLAY [logserver.rdoproject.org]
2025-10-08 12:46:43.441452 | 
2025-10-08 12:46:43.441526 | TASK [Set zuul-log-path fact]
2025-10-08 12:46:43.458366 | logserver.rdoproject.org | ok
2025-10-08 12:46:43.469426 | 
2025-10-08 12:46:43.469510 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 12:46:43.486789 | logserver.rdoproject.org | ok
2025-10-08 12:46:43.493883 | 
2025-10-08 12:46:43.493989 | TASK [upload-logs : Create log directories]
2025-10-08 12:46:45.317574 | logserver.rdoproject.org | changed
2025-10-08 12:46:45.320746 | 
2025-10-08 12:46:45.320842 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-08 12:46:45.561322 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005085
2025-10-08 12:46:45.566129 | 
2025-10-08 12:46:45.566216 | TASK [upload-logs : Upload logs to log server]
2025-10-08 12:46:47.269350 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-08 12:46:47.272470 | 
2025-10-08 12:46:47.272538 | LOOP [upload-logs : Compress console log and json output]
2025-10-08 12:46:47.313944 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:46:47.322859 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:46:47.330265 | 
2025-10-08 12:46:47.330372 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-08 12:46:47.368180 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:46:47.368424 | 
2025-10-08 12:46:47.372237 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 12:46:47.378329 | 
2025-10-08 12:46:47.378436 | LOOP [upload-logs : Upload console log and json output]