2025-09-30 05:01:09.928263 | Job console starting...
2025-09-30 05:01:10.411253 | Updating repositories
2025-09-30 05:01:11.301188 | Preparing job workspace
2025-09-30 05:01:30.977601 | Running Ansible setup...
2025-09-30 05:01:41.297456 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 05:01:44.664941 | 
2025-09-30 05:01:44.665609 | PLAY [localhost]
2025-09-30 05:01:44.710209 | 
2025-09-30 05:01:44.710316 | TASK [Gathering Facts]
2025-09-30 05:01:47.903218 | localhost | ok
2025-09-30 05:01:47.930095 | 
2025-09-30 05:01:47.930225 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 05:01:49.645608 | localhost -> localhost | changed
2025-09-30 05:01:49.651204 | 
2025-09-30 05:01:49.651278 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 05:01:53.035273 | localhost -> localhost | changed
2025-09-30 05:01:53.045384 | 
2025-09-30 05:01:53.045476 | TASK [Setup log path fact]
2025-09-30 05:01:53.099967 | localhost | ok
2025-09-30 05:01:53.212420 | 
2025-09-30 05:01:53.212540 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 05:01:53.318922 | localhost | ok
2025-09-30 05:01:53.326827 | 
2025-09-30 05:01:53.326900 | TASK [emit-job-header : Print job information]
2025-09-30 05:01:53.512643 | # Job Information
2025-09-30 05:01:53.512880 | Ansible Version: 2.15.12
2025-09-30 05:01:53.513685 | Job: cifmw-molecule-nat64_appliance
2025-09-30 05:01:53.513737 | Pipeline: github-check
2025-09-30 05:01:53.513765 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-09-30 05:01:53.513786 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333
2025-09-30 05:01:53.513806 | Log URL (when completed): https://logserver.rdoproject.org/5f2/rdoproject.org/5f2f0fc6adde475cbb7e8a43812a991d/
2025-09-30 05:01:53.513825 | Event ID: 3089cae0-9dba-11f0-9d66-59f03df1d747
2025-09-30 05:01:53.518317 | 
2025-09-30 05:01:53.518393 | LOOP [emit-job-header : Print node information]
2025-09-30 05:01:54.177497 | localhost | ok:
2025-09-30 05:01:54.177676 | localhost | # Node Information
2025-09-30 05:01:54.177710 | localhost | Inventory Hostname: controller
2025-09-30 05:01:54.177737 | localhost | Hostname: np0005461615
2025-09-30 05:01:54.177760 | localhost | Username: zuul
2025-09-30 05:01:54.177783 | localhost | Distro: CentOS 9
2025-09-30 05:01:54.177803 | localhost | Provider: ibm-bm4-nodepool
2025-09-30 05:01:54.177823 | localhost | Region: regionOne
2025-09-30 05:01:54.177842 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-09-30 05:01:54.177861 | localhost | Product Name: OpenStack Compute
2025-09-30 05:01:54.177879 | localhost | Interface IP: 192.168.26.57
2025-09-30 05:01:54.244250 | 
2025-09-30 05:01:54.244347 | PLAY [all]
2025-09-30 05:01:54.257876 | 
2025-09-30 05:01:54.257971 | TASK [Gather network facts]
2025-09-30 05:01:54.668814 | controller | ok
2025-09-30 05:01:54.729577 | 
2025-09-30 05:01:54.729678 | TASK [include_role : start-zuul-console]
2025-09-30 05:01:54.841188 | controller | ok
2025-09-30 05:01:54.876934 | 
2025-09-30 05:01:54.877040 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 05:01:55.626709 | controller | ok
2025-09-30 05:01:55.645625 | 
2025-09-30 05:01:55.645713 | TASK [include_role : add-build-sshkey]
2025-09-30 05:01:55.718184 | controller | ok
2025-09-30 05:01:55.769232 | 
2025-09-30 05:01:55.769340 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 05:01:56.832855 | controller -> localhost | ok
2025-09-30 05:01:56.838266 | 
2025-09-30 05:01:56.838332 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 05:01:56.897248 | controller | ok
2025-09-30 05:01:56.933727 | controller | included: /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 05:01:56.956293 | 
2025-09-30 05:01:56.956374 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 05:01:59.214452 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 05:01:59.214657 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/5f2f0fc6adde475cbb7e8a43812a991d_id_rsa.
2025-09-30 05:01:59.214693 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/5f2f0fc6adde475cbb7e8a43812a991d_id_rsa.pub.
2025-09-30 05:01:59.214719 | controller -> localhost | The key fingerprint is:
2025-09-30 05:01:59.214740 | controller -> localhost | SHA256:uHaf4wWqKG9FnqH3DZEcwTbms+sza5AdNRXMQmHXFvA zuul-build-sshkey
2025-09-30 05:01:59.214762 | controller -> localhost | The key's randomart image is:
2025-09-30 05:01:59.214782 | controller -> localhost | +---[RSA 3072]----+
2025-09-30 05:01:59.214801 | controller -> localhost | |       ..o+==+.. |
2025-09-30 05:01:59.214820 | controller -> localhost | |        *.+.o.o  |
2025-09-30 05:01:59.214840 | controller -> localhost | |       = = o .E  |
2025-09-30 05:01:59.214859 | controller -> localhost | |      o.B        |
2025-09-30 05:01:59.214878 | controller -> localhost | |     +.=S=.      |
2025-09-30 05:01:59.214897 | controller -> localhost | |    . B.+. .     |
2025-09-30 05:01:59.214942 | controller -> localhost | |     oooo+  .    |
2025-09-30 05:01:59.214969 | controller -> localhost | |  . .o o*.oo     |
2025-09-30 05:01:59.215009 | controller -> localhost | |   +o .oo=+.     |
2025-09-30 05:01:59.215038 | controller -> localhost | +----[SHA256]-----+
2025-09-30 05:01:59.215082 | controller -> localhost | ok: Runtime: 0:00:00.861264
2025-09-30 05:01:59.224876 | 
2025-09-30 05:01:59.227313 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 05:01:59.285944 | controller | ok
2025-09-30 05:01:59.297013 | controller | included: /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 05:01:59.330055 | 
2025-09-30 05:01:59.330168 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 05:01:59.419592 | controller | skipping: Conditional result was False
2025-09-30 05:01:59.425212 | 
2025-09-30 05:01:59.425288 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 05:02:00.352050 | controller | changed
2025-09-30 05:02:00.361993 | 
2025-09-30 05:02:00.362571 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 05:02:00.621033 | controller | ok
2025-09-30 05:02:00.774645 | 
2025-09-30 05:02:00.774757 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 05:02:01.652822 | controller | changed
2025-09-30 05:02:01.667351 | 
2025-09-30 05:02:01.667616 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 05:02:02.490665 | controller | changed
2025-09-30 05:02:02.499358 | 
2025-09-30 05:02:02.499453 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 05:02:02.547301 | controller | skipping: Conditional result was False
2025-09-30 05:02:02.553769 | 
2025-09-30 05:02:02.553862 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 05:02:03.464387 | controller -> localhost | changed
2025-09-30 05:02:03.479727 | 
2025-09-30 05:02:03.479801 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 05:02:04.504132 | controller -> localhost | Identity added: /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/5f2f0fc6adde475cbb7e8a43812a991d_id_rsa (zuul-build-sshkey)
2025-09-30 05:02:04.504323 | controller -> localhost | ok: Runtime: 0:00:00.030566
2025-09-30 05:02:04.511472 | 
2025-09-30 05:02:04.511545 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 05:02:04.996438 | controller | ok
2025-09-30 05:02:05.002133 | 
2025-09-30 05:02:05.002242 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 05:02:05.106844 | controller | skipping: Conditional result was False
2025-09-30 05:02:05.121945 | 
2025-09-30 05:02:05.122021 | TASK [include_role : validate-host]
2025-09-30 05:02:05.190351 | controller | ok
2025-09-30 05:02:05.288292 | 
2025-09-30 05:02:05.288675 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-30 05:02:05.437813 | controller | ok
2025-09-30 05:02:05.444437 | 
2025-09-30 05:02:05.444504 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-30 05:02:06.437413 | controller -> localhost | ok
2025-09-30 05:02:06.458846 | 
2025-09-30 05:02:06.458962 | TASK [validate-host : Collect information about the host]
2025-09-30 05:02:07.132369 | controller | ok
2025-09-30 05:02:07.153370 | 
2025-09-30 05:02:07.153445 | TASK [validate-host : Sanitize hostname]
2025-09-30 05:02:07.336956 | controller | ok
2025-09-30 05:02:07.342326 | 
2025-09-30 05:02:07.342396 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-30 05:02:09.083166 | controller -> localhost | changed
2025-09-30 05:02:09.089103 | 
2025-09-30 05:02:09.089254 | TASK [validate-host : Collect information about zuul worker]
2025-09-30 05:02:10.228898 | controller | ok
2025-09-30 05:02:10.242723 | 
2025-09-30 05:02:10.242804 | TASK [validate-host : Write out all zuul information for each host]
2025-09-30 05:02:11.748750 | controller -> localhost | changed
2025-09-30 05:02:11.761610 | 
2025-09-30 05:02:11.761694 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 05:02:11.820708 | controller | skipping: Conditional result was False
2025-09-30 05:02:11.826472 | 
2025-09-30 05:02:11.826562 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 05:02:11.870434 | controller | skipping: Conditional result was False
2025-09-30 05:02:11.878764 | 
2025-09-30 05:02:11.878843 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 05:02:12.247554 | controller | ok: "logs"
2025-09-30 05:02:12.247767 | controller | ok: All items complete
2025-09-30 05:02:12.247801 | 
2025-09-30 05:02:12.439353 | controller | ok: "artifacts"
2025-09-30 05:02:12.642378 | controller | ok: "docs"
2025-09-30 05:02:12.657303 | 
2025-09-30 05:02:12.657374 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 05:02:12.993758 | controller | changed: "logs"
2025-09-30 05:02:13.192363 | controller | changed: "artifacts"
2025-09-30 05:02:13.405380 | controller | changed: "docs"
2025-09-30 05:02:13.483180 | 
2025-09-30 05:02:13.483260 | PLAY RECAP
2025-09-30 05:02:13.483305 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 05:02:13.483334 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 05:02:13.483354 | 
2025-09-30 05:02:13.969508 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 05:02:13.970268 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-30 05:02:15.648942 | 
2025-09-30 05:02:15.649232 | PLAY [all]
2025-09-30 05:02:15.670842 | 
2025-09-30 05:02:15.670947 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-30 05:02:15.730745 | controller | ok
2025-09-30 05:02:15.735601 | 
2025-09-30 05:02:15.735680 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-30 05:02:16.315450 | controller | changed
2025-09-30 05:02:16.322047 | 
2025-09-30 05:02:16.322120 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-30 05:02:17.976817 | controller | changed
2025-09-30 05:02:17.997217 | 
2025-09-30 05:02:17.997298 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-09-30 05:02:18.637244 | controller | changed:
2025-09-30 05:02:18.637501 | controller | {
2025-09-30 05:02:18.637550 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-09-30 05:02:18.637585 | controller | }
2025-09-30 05:02:18.855269 | controller | changed:
2025-09-30 05:02:18.855359 | controller | {
2025-09-30 05:02:18.855391 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-09-30 05:02:18.855415 | controller | }
2025-09-30 05:02:19.084940 | controller | changed:
2025-09-30 05:02:19.085029 | controller | {
2025-09-30 05:02:19.085060 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-09-30 05:02:19.085082 | controller | }
2025-09-30 05:02:19.335975 | controller | changed:
2025-09-30 05:02:19.336067 | controller | {
2025-09-30 05:02:19.336095 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-09-30 05:02:19.336118 | controller | }
2025-09-30 05:02:19.567336 | controller | changed:
2025-09-30 05:02:19.567422 | controller | {
2025-09-30 05:02:19.567448 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-09-30 05:02:19.567469 | controller | }
2025-09-30 05:02:19.798701 | controller | changed:
2025-09-30 05:02:19.798945 | controller | {
2025-09-30 05:02:19.798991 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-09-30 05:02:19.799017 | controller | }
2025-09-30 05:02:20.030517 | controller | changed:
2025-09-30 05:02:20.030596 | controller | {
2025-09-30 05:02:20.030625 | 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-09-30 05:02:20.030648 | controller | }
2025-09-30 05:02:20.269859 | controller | changed:
2025-09-30 05:02:20.269958 | controller | {
2025-09-30 05:02:20.269989 | 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-09-30 05:02:20.270012 | controller | }
2025-09-30 05:02:20.502957 | controller | changed:
2025-09-30 05:02:20.503052 | controller | {
2025-09-30 05:02:20.503081 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-09-30 05:02:20.503103 | controller | }
2025-09-30 05:02:20.769514 | controller | changed:
2025-09-30 05:02:20.769615 | controller | {
2025-09-30 05:02:20.769642 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-09-30 05:02:20.769663 | controller | }
2025-09-30 05:02:20.949352 | controller | changed:
2025-09-30 05:02:20.949435 | controller | {
2025-09-30 05:02:20.949463 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-09-30 05:02:20.949484 | controller | }
2025-09-30 05:02:21.175733 | controller | changed:
2025-09-30 05:02:21.175835 | controller | {
2025-09-30 05:02:21.175862 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-09-30 05:02:21.175883 | controller | }
2025-09-30 05:02:21.405236 | controller | changed:
2025-09-30 05:02:21.405332 | controller | {
2025-09-30 05:02:21.405360 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-09-30 05:02:21.405382 | controller | }
2025-09-30 05:02:21.633719 | controller | changed:
2025-09-30 05:02:21.633807 | controller | {
2025-09-30 05:02:21.633835 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-09-30 05:02:21.633856 | controller | }
2025-09-30 05:02:21.851731 | controller | changed:
2025-09-30 05:02:21.851821 | controller | {
2025-09-30 05:02:21.851847 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-09-30 05:02:21.851869 | controller | }
2025-09-30 05:02:22.062807 | controller | changed:
2025-09-30 05:02:22.062899 | controller | {
2025-09-30 05:02:22.062949 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-09-30 05:02:22.062972 | controller | }
2025-09-30 05:02:22.275070 | controller | changed:
2025-09-30 05:02:22.275182 | controller | {
2025-09-30 05:02:22.275213 | 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-09-30 05:02:22.275237 | controller | }
2025-09-30 05:02:22.527692 | controller | changed:
2025-09-30 05:02:22.527787 | controller | {
2025-09-30 05:02:22.527814 | 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-09-30 05:02:22.527843 | controller | }
2025-09-30 05:02:22.763281 | controller | changed:
2025-09-30 05:02:22.763369 | controller | {
2025-09-30 05:02:22.763397 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-09-30 05:02:22.763420 | controller | }
2025-09-30 05:02:22.992524 | controller | changed:
2025-09-30 05:02:22.992604 | controller | {
2025-09-30 05:02:22.992967 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-09-30 05:02:22.992997 | controller | }
2025-09-30 05:02:23.248289 | controller | changed:
2025-09-30 05:02:23.248374 | controller | {
2025-09-30 05:02:23.248403 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-09-30 05:02:23.248424 | controller | }
2025-09-30 05:02:23.491855 | controller | changed:
2025-09-30 05:02:23.492009 | controller | {
2025-09-30 05:02:23.492042 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-09-30 05:02:23.492064 | controller | }
2025-09-30 05:02:23.703868 | controller | changed:
2025-09-30 05:02:23.703966 | controller | {
2025-09-30 05:02:23.703998 | 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-09-30 05:02:23.704021 | controller | }
2025-09-30 05:02:23.937100 | controller | changed:
2025-09-30 05:02:23.937185 | controller | {
2025-09-30 05:02:23.937214 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-09-30 05:02:23.937234 | controller | }
2025-09-30 05:02:24.163682 | controller | changed:
2025-09-30 05:02:24.163765 | controller | {
2025-09-30 05:02:24.163793 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-09-30 05:02:24.163816 | controller | }
2025-09-30 05:02:24.381678 | controller | changed:
2025-09-30 05:02:24.381767 | controller | {
2025-09-30 05:02:24.381794 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-09-30 05:02:24.381815 | controller | }
2025-09-30 05:02:24.415380 | 
2025-09-30 05:02:24.415491 | TASK [Set timezone to UTC]
2025-09-30 05:02:24.911564 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-09-30 05:02:24.919175 | 
2025-09-30 05:02:24.919266 | TASK [Create nodepool directory]
2025-09-30 05:02:25.156437 | controller | changed
2025-09-30 05:02:25.168511 | 
2025-09-30 05:02:25.168604 | TASK [Create nodepool sub_nodes file]
2025-09-30 05:02:25.777768 | controller | changed
2025-09-30 05:02:25.782601 | 
2025-09-30 05:02:25.782675 | TASK [Create nodepool sub_nodes_private file]
2025-09-30 05:02:26.462818 | controller | changed
2025-09-30 05:02:26.470139 | 
2025-09-30 05:02:26.470234 | LOOP [Populate nodepool sub_nodes file]
2025-09-30 05:02:26.532173 | 
2025-09-30 05:02:26.532331 | LOOP [Populate nodepool sub_nodes_private file]
2025-09-30 05:02:26.593410 | 
2025-09-30 05:02:26.593557 | TASK [Create nodepool primary file]
2025-09-30 05:02:26.647498 | controller | skipping: Conditional result was False
2025-09-30 05:02:26.654122 | 
2025-09-30 05:02:26.654221 | TASK [Create nodepool node_private for this node]
2025-09-30 05:02:27.324217 | controller | changed
2025-09-30 05:02:27.338545 | 
2025-09-30 05:02:27.338632 | LOOP [Copy ssh keys to nodepool directory]
2025-09-30 05:02:27.785411 | controller | ok: Item: id_rsa Runtime: 0:00:00.007454
2025-09-30 05:02:27.785809 | 
2025-09-30 05:02:27.990625 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.007372
2025-09-30 05:02:27.997139 | 
2025-09-30 05:02:27.997264 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-09-30 05:02:28.610392 | controller | changed
2025-09-30 05:02:28.624941 | 
2025-09-30 05:02:28.625032 | TASK [Validate sudoers config after edits]
2025-09-30 05:02:28.875339 | controller | /etc/sudoers: parsed OK
2025-09-30 05:02:28.875407 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-09-30 05:02:28.875416 | controller | /etc/sudoers.d/zuul: parsed OK
2025-09-30 05:02:28.875422 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-09-30 05:02:29.165055 | controller | ok: Runtime: 0:00:00.005850
2025-09-30 05:02:29.170523 | 
2025-09-30 05:02:29.170589 | TASK [Show the environment passed in to job shell scripts]
2025-09-30 05:02:29.392018 | controller | SHELL=/bin/bash
2025-09-30 05:02:29.392070 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-09-30 05:02:29.392080 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-09-30 05:02:29.392087 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/46/3346/eb5b53fb17db92a72d33d052a56c8edd0d10ea78^openstack-k8s-operators/ci-framework:main:refs/changes/33/3333/b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 05:02:29.392095 | controller | PWD=/home/zuul
2025-09-30 05:02:29.392101 | controller | ZUUL_PIPELINE=github-check
2025-09-30 05:02:29.392106 | controller | LOGNAME=zuul
2025-09-30 05:02:29.392112 | controller | XDG_SESSION_TYPE=tty
2025-09-30 05:02:29.392117 | controller | _=/usr/bin/env
2025-09-30 05:02:29.392176 | controller | MOTD_SHOWN=pam
2025-09-30 05:02:29.392201 | controller | HOME=/home/zuul
2025-09-30 05:02:29.392210 | controller | LANG=en_US.UTF-8
2025-09-30 05:02:29.392216 | controller | SSH_CONNECTION=192.168.26.12 54218 192.168.26.57 22
2025-09-30 05:02:29.392222 | 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-09-30 05:02:29.392228 | controller | ZUUL_CHANGE_IDS=3346,eb5b53fb17db92a72d33d052a56c8edd0d10ea78 3333,b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 05:02:29.392233 | controller | WORKSPACE=/home/zuul/workspace
2025-09-30 05:02:29.392238 | controller | XDG_SESSION_CLASS=user
2025-09-30 05:02:29.392244 | controller | SELINUX_ROLE_REQUESTED=
2025-09-30 05:02:29.392249 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-09-30 05:02:29.392255 | controller | USER=zuul
2025-09-30 05:02:29.392261 | controller | ZUUL_VOTING=True
2025-09-30 05:02:29.392266 | controller | BUILD_TIMEOUT=1800000
2025-09-30 05:02:29.392271 | controller | SELINUX_USE_CURRENT_RANGE=
2025-09-30 05:02:29.392276 | controller | SHLVL=1
2025-09-30 05:02:29.392282 | controller | ZUUL_PATCHSET=b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-30 05:02:29.392287 | controller | XDG_SESSION_ID=1
2025-09-30 05:02:29.392293 | controller | ZUUL_BRANCH=main
2025-09-30 05:02:29.392298 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-09-30 05:02:29.392304 | controller | SSH_CLIENT=192.168.26.12 54218 22
2025-09-30 05:02:29.392309 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-09-30 05:02:29.392314 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-09-30 05:02:29.392320 | controller | which_declare=declare -f
2025-09-30 05:02:29.392326 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-09-30 05:02:29.392332 | controller | SELINUX_LEVEL_REQUESTED=
2025-09-30 05:02:29.392337 | controller | ZUUL_CHANGE=3333
2025-09-30 05:02:29.392342 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-09-30 05:02:29.392348 | controller | ZUUL_UUID=5f2f0fc6adde475cbb7e8a43812a991d
2025-09-30 05:02:29.392353 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-09-30 05:02:29.392358 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-09-30 05:02:29.392364 | controller | }
2025-09-30 05:02:29.700885 | controller | ok: Runtime: 0:00:00.007050
2025-09-30 05:02:29.708278 | 
2025-09-30 05:02:29.708348 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-09-30 05:02:29.733716 | controller | skipping: Conditional result was False
2025-09-30 05:02:29.740157 | 
2025-09-30 05:02:29.740235 | TASK [Symlink /home/zuul-worker/workspace]
2025-09-30 05:02:30.268719 | controller | skipping: Conditional result was False
2025-09-30 05:02:30.274619 | 
2025-09-30 05:02:30.274694 | TASK [Ensure legacy workspace directory]
2025-09-30 05:02:30.465230 | controller | changed
2025-09-30 05:02:30.505171 | 
2025-09-30 05:02:30.505250 | PLAY RECAP
2025-09-30 05:02:30.505291 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 05:02:30.505314 | 
2025-09-30 05:02:30.571503 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-30 05:02:30.572290 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/read_global_vars.yml@main]
2025-09-30 05:02:31.112767 | 
2025-09-30 05:02:31.112869 | PLAY [Load global variables]
2025-09-30 05:02:31.134747 | 
2025-09-30 05:02:31.134851 | TASK [Read group_vars all file]
2025-09-30 05:02:31.174344 | controller | ok
2025-09-30 05:02:31.191480 | 
2025-09-30 05:02:31.191591 | TASK [cifmw_helpers : Check if file is available]
2025-09-30 05:02:31.463297 | controller | ok
2025-09-30 05:02:31.469657 | 
2025-09-30 05:02:31.469747 | TASK [cifmw_helpers : Read vars]
2025-09-30 05:02:31.489507 | 
2025-09-30 05:02:31.489652 | LOOP [cifmw_helpers : Set vars as fact]
2025-09-30 05:02:31.578861 | 
2025-09-30 05:02:31.579032 | PLAY RECAP
2025-09-30 05:02:31.579083 | controller | ok: 1 changed: 0 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 05:02:31.579109 | 
2025-09-30 05:02:31.665288 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/read_global_vars.yml@main]
2025-09-30 05:02:31.666049 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-30 05:02:32.238926 | 
2025-09-30 05:02:32.239029 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-09-30 05:02:32.265779 | 
2025-09-30 05:02:32.265870 | TASK [Create zuul-output directory]
2025-09-30 05:02:32.590695 | controller | changed
2025-09-30 05:02:32.595628 | 
2025-09-30 05:02:32.595699 | TASK [Slurp Zuul inventory test]
2025-09-30 05:02:32.912603 | controller -> localhost | ok
2025-09-30 05:02:32.919103 | 
2025-09-30 05:02:32.919180 | TASK [Save zuul inventory]
2025-09-30 05:02:33.776637 | controller | changed
2025-09-30 05:02:33.781523 | 
2025-09-30 05:02:33.781593 | TASK [Save zuul vars without the change_message]
2025-09-30 05:02:34.402979 | controller | changed
2025-09-30 05:02:34.421887 | 
2025-09-30 05:02:34.422071 | PLAY RECAP
2025-09-30 05:02:34.422124 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 05:02:34.422149 | 
2025-09-30 05:02:34.504299 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-30 05:02:34.505136 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-30 05:02:35.074525 | 
2025-09-30 05:02:35.074634 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-09-30 05:02:35.096329 | 
2025-09-30 05:02:35.096407 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-09-30 05:02:35.126290 | controller | ok
2025-09-30 05:02:35.152386 | 
2025-09-30 05:02:35.152489 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-30 05:02:35.186200 | controller | skipping: Conditional result was False
2025-09-30 05:02:35.191589 | 
2025-09-30 05:02:35.191660 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-30 05:02:35.523752 | controller | ok
2025-09-30 05:02:35.531097 | 
2025-09-30 05:02:35.531201 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-30 05:02:36.225248 | controller | ok
2025-09-30 05:02:36.238631 | 
2025-09-30 05:02:36.238735 | TASK [Prepare workspace]
2025-09-30 05:02:36.269471 | controller | ok
2025-09-30 05:02:36.292732 | 
2025-09-30 05:02:36.292840 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 05:02:36.677433 | controller | ok
2025-09-30 05:02:36.684742 | 
2025-09-30 05:02:36.685119 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 05:02:38.868948 | controller | Output suppressed because no_log was given
2025-09-30 05:02:38.878865 | 
2025-09-30 05:02:38.878978 | LOOP [Create zuul-output directory]
2025-09-30 05:02:39.064164 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-09-30 05:02:39.220043 | controller | ok: "/home/zuul/zuul-output/logs"
2025-09-30 05:02:39.226046 | 
2025-09-30 05:02:39.226111 | TASK [Install required packages]
2025-09-30 05:03:32.045725 | controller | changed
2025-09-30 05:03:32.051265 | 
2025-09-30 05:03:32.051334 | TASK [Install venv]
2025-09-30 05:04:36.112400 | controller | changed
2025-09-30 05:04:36.137840 | 
2025-09-30 05:04:36.137932 | PLAY RECAP
2025-09-30 05:04:36.137983 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 05:04:36.138009 | 
2025-09-30 05:04:36.219830 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-30 05:04:36.220690 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-30 05:04:36.758270 | 
2025-09-30 05:04:36.758366 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-09-30 05:04:36.779467 | 
2025-09-30 05:04:36.779569 | TASK [Gather required facts]
2025-09-30 05:04:37.298628 | controller | ok
2025-09-30 05:04:37.314860 | 
2025-09-30 05:04:37.314983 | TASK [Load environment var if instructed to]
2025-09-30 05:04:37.339037 | controller | skipping: Conditional result was False
2025-09-30 05:04:37.344540 | 
2025-09-30 05:04:37.344611 | TASK [Run molecule]
2025-09-30 05:04:38.354355 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-09-30 05:04:38.423588 | controller | INFO     Performing prerun with role_name_check=0...
2025-09-30 05:04:55.336987 | 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-09-30 05:04:55.337500 | 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-09-30 05:04:55.337991 | 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-09-30 05:04:55.338470 | 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-09-30 05:04:55.338951 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+e2f9c552 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+e2f9c552 (/home/zuul/.ansible/collections/ansible_collections).
2025-09-30 05:04:55.339436 | 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-09-30 05:04:55.339864 | 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-09-30 05:04:55.340355 | 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-09-30 05:04:55.340792 | 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-09-30 05:04:55.341256 | 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-09-30 05:04:55.341858 | 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-09-30 05:04:55.342323 | 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-09-30 05:04:55.342777 | 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-09-30 05:04:55.343234 | 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-09-30 05:04:55.343687 | 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-09-30 05:04:55.354945 | controller | INFO     Running default > prepare
2025-09-30 05:04:56.076501 | controller |
2025-09-30 05:04:56.076581 | controller | PLAY [Prepare] *****************************************************************
2025-09-30 05:04:56.076686 | controller |
2025-09-30 05:04:56.076793 | controller | TASK [Gathering Facts] *********************************************************
2025-09-30 05:04:56.076895 | controller | Tuesday 30 September 2025  05:04:56 +0000 (0:00:00.021)       0:00:00.021 *****
2025-09-30 05:04:56.995597 | controller | ok: [instance]
2025-09-30 05:04:56.995661 | controller |
2025-09-30 05:04:56.995768 | controller | TASK [Create custom basedir] ***************************************************
2025-09-30 05:04:56.995876 | controller | Tuesday 30 September 2025  05:04:56 +0000 (0:00:00.919)       0:00:00.941 *****
2025-09-30 05:04:57.344369 | controller | ok: [instance]
2025-09-30 05:04:57.344431 | controller |
2025-09-30 05:04:57.344544 | controller | TASK [Install some debug utils] ************************************************
2025-09-30 05:04:57.344655 | controller | Tuesday 30 September 2025  05:04:57 +0000 (0:00:00.348)       0:00:01.290 *****
2025-09-30 05:05:01.766090 | controller | changed: [instance]
2025-09-30 05:05:01.766215 | controller |
2025-09-30 05:05:01.766238 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-09-30 05:05:01.787216 | controller | Tuesday 30 September 2025  05:05:01 +0000 (0:00:04.420)       0:00:05.711 *****
2025-09-30 05:05:01.787239 | controller | skipping: [instance]
2025-09-30 05:05:01.787335 | controller |
2025-09-30 05:05:01.787455 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-09-30 05:05:01.787555 | controller | Tuesday 30 September 2025  05:05:01 +0000 (0:00:00.022)       0:00:05.733 *****
2025-09-30 05:05:01.835052 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-09-30 05:05:01.835160 | controller |
2025-09-30 05:05:01.835336 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-09-30 05:05:01.835463 | controller | Tuesday 30 September 2025  05:05:01 +0000 (0:00:00.047)       0:00:05.780 *****
2025-09-30 05:05:02.140046 | controller | ok: [instance]
2025-09-30 05:05:02.140494 | controller |
2025-09-30 05:05:02.370791 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-09-30 05:05:02.370863 | controller | Tuesday 30 September 2025  05:05:02 +0000 (0:00:00.305)       0:00:06.086 *****
2025-09-30 05:05:02.370882 | controller | ok: [instance]
2025-09-30 05:05:02.370909 | controller |
2025-09-30 05:05:02.370918 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-09-30 05:05:02.370972 | controller | Tuesday 30 September 2025  05:05:02 +0000 (0:00:00.230)       0:00:06.316 *****
2025-09-30 05:05:03.120419 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-09-30 05:05:03.120959 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-09-30 05:05:03.180665 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-09-30 05:05:03.180713 | controller |
2025-09-30 05:05:03.180722 | controller | TASK [Deploy repo-setup] *******************************************************
2025-09-30 05:05:03.180729 | controller | Tuesday 30 September 2025  05:05:03 +0000 (0:00:00.749)       0:00:07.066 *****
2025-09-30 05:05:03.180741 | controller |
2025-09-30 05:05:03.766299 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-09-30 05:05:03.766343 | controller | Tuesday 30 September 2025  05:05:03 +0000 (0:00:00.060)       0:00:07.126 *****
2025-09-30 05:05:03.766356 | controller | changed: [instance] => (item=tmp)
2025-09-30 05:05:03.766996 | controller | changed: [instance] => (item=artifacts/repositories)
2025-09-30 05:05:04.461740 | controller | changed: [instance] => (item=venv/repo_setup)
2025-09-30 05:05:04.461778 | controller |
2025-09-30 05:05:04.461793 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-09-30 05:05:04.461802 | controller | Tuesday 30 September 2025  05:05:03 +0000 (0:00:00.585)       0:00:07.712 *****
2025-09-30 05:05:04.461813 | controller | ok: [instance]
2025-09-30 05:05:05.658689 | controller |
2025-09-30 05:05:05.658736 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-09-30 05:05:05.658745 | controller | Tuesday 30 September 2025  05:05:04 +0000 (0:00:00.695)       0:00:08.407 *****
2025-09-30 05:05:05.658756 | controller | changed: [instance]
2025-09-30 05:05:13.788238 | controller |
2025-09-30 05:05:13.788277 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-09-30 05:05:13.788286 | controller | Tuesday 30 September 2025  05:05:05 +0000 (0:00:01.196)       0:00:09.604 *****
2025-09-30 05:05:13.788296 | controller | changed: [instance]
2025-09-30 05:05:14.526854 | controller |
2025-09-30 05:05:14.526897 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-09-30 05:05:14.526907 | controller | Tuesday 30 September 2025  05:05:13 +0000 (0:00:08.128)       0:00:17.732 *****
2025-09-30 05:05:14.526918 | controller | changed: [instance]
2025-09-30 05:05:14.553920 | controller |
2025-09-30 05:05:14.553952 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-09-30 05:05:14.553961 | controller | Tuesday 30 September 2025  05:05:14 +0000 (0:00:00.739)       0:00:18.472 *****
2025-09-30 05:05:14.553971 | controller | skipping: [instance]
2025-09-30 05:05:15.400059 | controller |
2025-09-30 05:05:15.400098 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-09-30 05:05:15.400107 | controller | Tuesday 30 September 2025  05:05:14 +0000 (0:00:00.027)       0:00:18.500 *****
2025-09-30 05:05:15.400118 | controller | changed: [instance]
2025-09-30 05:05:15.437650 | controller |
2025-09-30 05:05:15.437681 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-09-30 05:05:15.437689 | controller | Tuesday 30 September 2025  05:05:15 +0000 (0:00:00.845)       0:00:19.345 *****
2025-09-30 05:05:15.437700 | controller | skipping: [instance]
2025-09-30 05:05:15.478381 | controller |
2025-09-30 05:05:15.478440 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-09-30 05:05:15.478451 | controller | Tuesday 30 September 2025  05:05:15 +0000 (0:00:00.038)       0:00:19.383 *****
2025-09-30 05:05:15.478467 | controller | skipping: [instance]
2025-09-30 05:05:15.520392 | controller |
2025-09-30 05:05:15.520479 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-09-30 05:05:15.520489 | controller | Tuesday 30 September 2025  05:05:15 +0000 (0:00:00.040)       0:00:19.424 *****
2025-09-30 05:05:15.520503 | controller | skipping: [instance]
2025-09-30 05:05:16.089114 | controller |
2025-09-30 05:05:16.089150 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-09-30 05:05:16.089159 | controller | Tuesday 30 September 2025  05:05:15 +0000 (0:00:00.041)       0:00:19.465 *****
2025-09-30 05:05:16.089273 | controller | changed: [instance]
2025-09-30 05:05:16.542937 | controller |
2025-09-30 05:05:16.542980 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-09-30 05:05:16.542989 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.569)       0:00:20.035 *****
2025-09-30 05:05:16.543004 | controller | changed: [instance]
2025-09-30 05:05:16.578295 | controller |
2025-09-30 05:05:16.578341 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-09-30 05:05:16.578351 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.453)       0:00:20.488 *****
2025-09-30 05:05:16.578363 | controller | skipping: [instance]
2025-09-30 05:05:16.578609 | controller |
2025-09-30 05:05:16.578634 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-09-30 05:05:16.612274 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.035)       0:00:20.524 *****
2025-09-30 05:05:16.612312 | controller | skipping: [instance]
2025-09-30 05:05:16.642256 | controller |
2025-09-30 05:05:16.642286 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-09-30 05:05:16.642295 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.033)       0:00:20.557 *****
2025-09-30 05:05:16.642308 | controller | skipping: [instance]
2025-09-30 05:05:16.642502 | controller |
2025-09-30 05:05:16.642681 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-09-30 05:05:16.642845 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.030)       0:00:20.588 *****
2025-09-30 05:05:16.679876 | controller | ok: [instance]
2025-09-30 05:05:16.680056 | controller |
2025-09-30 05:05:16.680270 | controller | TASK [repo_setup : Create download directory] **********************************
2025-09-30 05:05:16.680444 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.037)       0:00:20.626 *****
2025-09-30 05:05:16.706861 | controller | skipping: [instance]
2025-09-30 05:05:16.707033 | controller |
2025-09-30 05:05:16.707207 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-09-30 05:05:16.707369 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.026)       0:00:20.653 *****
2025-09-30 05:05:16.735407 | controller | skipping: [instance]
2025-09-30 05:05:16.735605 | controller |
2025-09-30 05:05:16.735787 | controller | TASK [Download the RPM] ********************************************************
2025-09-30 05:05:16.735956 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.028)       0:00:20.681 *****
2025-09-30 05:05:16.766079 | controller | skipping: [instance]
2025-09-30 05:05:16.766297 | controller |
2025-09-30 05:05:16.766446 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-09-30 05:05:16.766585 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.030)       0:00:20.712 *****
2025-09-30 05:05:16.801740 | controller | skipping: [instance]
2025-09-30 05:05:16.834294 | controller |
2025-09-30 05:05:16.834334 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-09-30 05:05:16.834343 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.035)       0:00:20.747 *****
2025-09-30 05:05:16.834355 | controller | skipping: [instance]
2025-09-30 05:05:16.866740 | controller |
2025-09-30 05:05:16.866782 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-09-30 05:05:16.866791 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.032)       0:00:20.780 *****
2025-09-30 05:05:16.866803 | controller | skipping: [instance]
2025-09-30 05:05:16.897790 | controller |
2025-09-30 05:05:16.897829 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-09-30 05:05:16.897837 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.032)       0:00:20.812 *****
2025-09-30 05:05:16.897852 | controller | skipping: [instance]
2025-09-30 05:05:17.093212 | controller |
2025-09-30 05:05:17.093247 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-09-30 05:05:17.093256 | controller | Tuesday 30 September 2025  05:05:16 +0000 (0:00:00.031)       0:00:20.843 *****
2025-09-30 05:05:17.093267 | controller | ok: [instance]
2025-09-30 05:05:17.322728 | controller |
2025-09-30 05:05:17.322768 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-09-30 05:05:17.322776 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.195)       0:00:21.039 *****
2025-09-30 05:05:17.322788 | controller | changed: [instance]
2025-09-30 05:05:17.584290 | controller |
2025-09-30 05:05:17.584333 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-09-30 05:05:17.584342 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.229)       0:00:21.268 *****
2025-09-30 05:05:17.584354 | controller | changed: [instance]
2025-09-30 05:05:17.610334 | controller |
2025-09-30 05:05:17.610382 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-09-30 05:05:17.610391 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.261)       0:00:21.529 *****
2025-09-30 05:05:17.610403 | controller | skipping: [instance]
2025-09-30 05:05:17.610432 | controller |
2025-09-30 05:05:17.610691 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-09-30 05:05:17.640316 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.026)       0:00:21.556 *****
2025-09-30 05:05:17.640370 | controller | skipping: [instance]
2025-09-30 05:05:17.640446 | controller |
2025-09-30 05:05:17.640484 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-09-30 05:05:17.640500 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.030)       0:00:21.586 *****
2025-09-30 05:05:17.665378 | controller | skipping: [instance]
2025-09-30 05:05:17.665556 | controller |
2025-09-30 05:05:17.665726 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-09-30 05:05:17.665890 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.025)       0:00:21.611 *****
2025-09-30 05:05:17.691983 | controller | skipping: [instance]
2025-09-30 05:05:17.692157 | controller |
2025-09-30 05:05:17.692341 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-09-30 05:05:17.692498 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.026)       0:00:21.638 *****
2025-09-30 05:05:17.717626 | controller | skipping: [instance]
2025-09-30 05:05:17.717800 | controller |
2025-09-30 05:05:17.717955 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-09-30 05:05:17.718090 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.025)       0:00:21.664 *****
2025-09-30 05:05:17.745249 | controller | skipping: [instance]
2025-09-30 05:05:17.745384 | controller |
2025-09-30 05:05:17.745542 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-09-30 05:05:17.745652 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.027)       0:00:21.691 *****
2025-09-30 05:05:17.769836 | controller | skipping: [instance]
2025-09-30 05:05:17.804639 | controller |
2025-09-30 05:05:17.804669 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-09-30 05:05:17.804678 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.024)       0:00:21.715 *****
2025-09-30 05:05:17.804688 | controller | skipping: [instance]
2025-09-30 05:05:17.827318 | controller |
2025-09-30 05:05:17.827345 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-09-30 05:05:17.827353 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.034)       0:00:21.750 *****
2025-09-30 05:05:17.827363 | controller | skipping: [instance]
2025-09-30 05:05:17.859700 | controller |
2025-09-30 05:05:17.859726 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-09-30 05:05:17.859734 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.022)       0:00:21.773 *****
2025-09-30 05:05:17.859744 | controller | skipping: [instance]
2025-09-30 05:05:17.891540 | controller |
2025-09-30 05:05:17.891568 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-09-30 05:05:17.891575 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.032)       0:00:21.805 *****
2025-09-30 05:05:17.891585 | controller | skipping: [instance]
2025-09-30 05:05:17.922787 | controller |
2025-09-30 05:05:17.922814 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-09-30 05:05:17.922821 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.032)       0:00:21.837 *****
2025-09-30 05:05:17.922831 | controller | skipping: [instance]
2025-09-30 05:05:17.953514 | controller |
2025-09-30 05:05:17.953557 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-09-30 05:05:17.953567 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.031)       0:00:21.869 *****
2025-09-30 05:05:17.953581 | controller | skipping: [instance]
2025-09-30 05:05:17.953741 | controller |
2025-09-30 05:05:17.953761 | controller | TASK [test_deps : Install additional packages] *********************************
2025-09-30 05:05:17.985896 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.030)       0:00:21.899 *****
2025-09-30 05:05:17.985941 | controller | skipping: [instance]
2025-09-30 05:06:02.749939 | controller |
2025-09-30 05:06:02.749982 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-09-30 05:06:02.749991 | controller | Tuesday 30 September 2025  05:05:17 +0000 (0:00:00.032)       0:00:21.931 *****
2025-09-30 05:06:02.750002 | controller | ok: [instance]
2025-09-30 05:06:03.947513 | controller |
2025-09-30 05:06:03.947546 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-09-30 05:06:03.947554 | controller | Tuesday 30 September 2025  05:06:02 +0000 (0:00:44.761)       0:01:06.693 *****
2025-09-30 05:06:03.947564 | controller | ok: [instance]
2025-09-30 05:06:03.980228 | controller |
2025-09-30 05:06:03.980259 | controller | TASK [test_deps : Install extra packages] **************************************
2025-09-30 05:06:03.980268 | controller | Tuesday 30 September 2025  05:06:03 +0000 (0:00:01.200)       0:01:07.893 *****
2025-09-30 05:06:03.980280 | controller | skipping: [instance]
2025-09-30 05:06:04.180656 | controller |
2025-09-30 05:06:04.180686 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-09-30 05:06:04.180694 | controller | Tuesday 30 September 2025  05:06:03 +0000 (0:00:00.032)       0:01:07.926 *****
2025-09-30 05:06:04.180704 | controller | ok: [instance]
2025-09-30 05:06:04.373284 | controller |
2025-09-30 05:06:04.373318 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-09-30 05:06:04.373332 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.200)       0:01:08.126 *****
2025-09-30 05:06:04.373343 | controller | changed: [instance]
2025-09-30 05:06:04.373362 | controller |
2025-09-30 05:06:04.373554 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-09-30 05:06:04.566657 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.192)       0:01:08.319 *****
2025-09-30 05:06:04.566692 | controller | ok: [instance]
2025-09-30 05:06:04.596836 | controller |
2025-09-30 05:06:04.596864 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-09-30 05:06:04.596872 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.192)       0:01:08.512 *****
2025-09-30 05:06:04.596882 | controller | skipping: [instance]
2025-09-30 05:06:04.615660 | controller |
2025-09-30 05:06:04.615687 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-09-30 05:06:04.615694 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.030)       0:01:08.542 *****
2025-09-30 05:06:04.615704 | controller | skipping: [instance]
2025-09-30 05:06:04.638509 | controller |
2025-09-30 05:06:04.638602 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-09-30 05:06:04.638614 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.018)       0:01:08.561 *****
2025-09-30 05:06:04.638634 | controller | ok: [instance]
2025-09-30 05:06:04.668923 | controller |
2025-09-30 05:06:04.668958 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-09-30 05:06:04.668966 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.022)       0:01:08.584 *****
2025-09-30 05:06:04.668976 | controller | skipping: [instance]
2025-09-30 05:07:20.695003 | controller |
2025-09-30 05:07:20.695038 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-09-30 05:07:20.695046 | controller | Tuesday 30 September 2025  05:06:04 +0000 (0:00:00.030)       0:01:08.614 *****
2025-09-30 05:07:20.695057 | controller | changed: [instance]
2025-09-30 05:07:20.903512 | controller |
2025-09-30 05:07:20.903542 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-09-30 05:07:20.903550 | controller | Tuesday 30 September 2025  05:07:20 +0000 (0:01:16.026)       0:02:24.641 *****
2025-09-30 05:07:20.903560 | controller | changed: [instance]
2025-09-30 05:07:21.282759 | controller |
2025-09-30 05:07:21.282790 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-09-30 05:07:21.282799 | controller | Tuesday 30 September 2025  05:07:20 +0000 (0:00:00.208)       0:02:24.849 *****
2025-09-30 05:07:21.282810 | controller | changed: [instance]
2025-09-30 05:07:21.867274 | controller |
2025-09-30 05:07:21.867308 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-09-30 05:07:21.867317 | controller | Tuesday 30 September 2025  05:07:21 +0000 (0:00:00.379)       0:02:25.228 *****
2025-09-30 05:07:21.867328 | controller | changed: [instance]
2025-09-30 05:07:21.867489 | controller |
2025-09-30 05:07:21.867509 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-09-30 05:07:22.065308 | controller | Tuesday 30 September 2025  05:07:21 +0000 (0:00:00.584)       0:02:25.813 *****
2025-09-30 05:07:22.065354 | controller | ok: [instance]
2025-09-30 05:07:22.065378 | controller |
2025-09-30 05:07:22.065606 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-09-30 05:07:22.776434 | controller | Tuesday 30 September 2025  05:07:22 +0000 (0:00:00.197)       0:02:26.011 *****
2025-09-30 05:07:22.776475 | controller | ok: [instance]
2025-09-30 05:07:22.776771 | controller |
2025-09-30 05:07:23.630267 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-09-30 05:07:23.630299 | controller | Tuesday 30 September 2025  05:07:22 +0000 (0:00:00.711)       0:02:26.722 *****
2025-09-30 05:07:23.630319 | controller | changed: [instance]
2025-09-30 05:07:23.630345 | controller |
2025-09-30 05:07:23.630519 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-09-30 05:07:23.709957 | controller | Tuesday 30 September 2025  05:07:23 +0000 (0:00:00.853)       0:02:27.576 *****
2025-09-30 05:07:23.709993 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-09-30 05:07:24.055383 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-09-30 05:07:24.055413 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-09-30 05:07:24.055420 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-09-30 05:07:24.055426 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-09-30 05:07:24.055432 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-09-30 05:07:24.055437 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-09-30 05:07:24.055443 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-09-30 05:07:24.055448 | controller |
2025-09-30 05:07:24.055454 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-09-30 05:07:24.055460 | controller | Tuesday 30 September 2025  05:07:23 +0000 (0:00:00.078)       0:02:27.655 *****
2025-09-30 05:07:24.055470 | controller | changed: [instance]
2025-09-30 05:07:24.396991 | controller |
2025-09-30 05:07:24.397025 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-09-30 05:07:24.397033 | controller | Tuesday 30 September 2025  05:07:24 +0000 (0:00:00.346)       0:02:28.001 *****
2025-09-30 05:07:24.397051 | controller | changed: [instance]
2025-09-30 05:07:24.752966 | controller |
2025-09-30 05:07:24.753000 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-09-30 05:07:24.753009 | controller | Tuesday 30 September 2025  05:07:24 +0000 (0:00:00.341)       0:02:28.343 *****
2025-09-30 05:07:24.753019 | controller | changed: [instance]
2025-09-30 05:07:25.091534 | controller |
2025-09-30 05:07:25.091572 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-09-30 05:07:25.091581 | controller | Tuesday 30 September 2025  05:07:24 +0000 (0:00:00.355)       0:02:28.698 *****
2025-09-30 05:07:25.091591 | controller | changed: [instance]
2025-09-30 05:07:25.091747 | controller |
2025-09-30 05:07:25.091781 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-09-30 05:07:25.433339 | controller | Tuesday 30 September 2025  05:07:25 +0000 (0:00:00.338)       0:02:29.037 *****
2025-09-30 05:07:25.433384 | controller | changed: [instance]
2025-09-30 05:07:25.794298 | controller |
2025-09-30 05:07:25.794332 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-09-30 05:07:25.794343 | controller | Tuesday 30 September 2025  05:07:25 +0000 (0:00:00.341)       0:02:29.379 *****
2025-09-30 05:07:25.794355 | controller | changed: [instance]
2025-09-30 05:07:25.794383 | controller |
2025-09-30 05:07:25.794393 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-09-30 05:07:25.794480 | controller | Tuesday 30 September 2025  05:07:25 +0000 (0:00:00.361)       0:02:29.740 *****
2025-09-30 05:07:26.132782 | controller | changed: [instance]
2025-09-30 05:07:26.476981 | controller |
2025-09-30 05:07:26.477011 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-09-30 05:07:26.477020 | controller | Tuesday 30 September 2025  05:07:26 +0000 (0:00:00.338)       0:02:30.078 *****
2025-09-30 05:07:26.477030 | controller | changed: [instance]
2025-09-30 05:07:26.812612 | controller |
2025-09-30 05:07:26.812652 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-09-30 05:07:26.812661 | controller | Tuesday 30 September 2025  05:07:26 +0000 (0:00:00.344)       0:02:30.423 *****
2025-09-30 05:07:26.812671 | controller | changed: [instance]
2025-09-30 05:07:27.146813 | controller |
2025-09-30 05:07:27.146844 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-09-30 05:07:27.146853 | controller | Tuesday 30 September 2025  05:07:26 +0000 (0:00:00.335)       0:02:30.758 *****
2025-09-30 05:07:27.146862 | controller | changed: [instance]
2025-09-30 05:07:27.482833 | controller |
2025-09-30 05:07:27.482863 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-09-30 05:07:27.482871 | controller | Tuesday 30 September 2025  05:07:27 +0000 (0:00:00.334)       0:02:31.092 *****
2025-09-30 05:07:27.482881 | controller | changed: [instance]
2025-09-30 05:07:27.829104 | controller |
2025-09-30 05:07:27.829134 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-09-30 05:07:27.829142 | controller | Tuesday 30 September 2025  05:07:27 +0000 (0:00:00.336)       0:02:31.428 *****
2025-09-30 05:07:27.829152 | controller | changed: [instance]
2025-09-30 05:07:28.177905 | controller |
2025-09-30 05:07:28.177936 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-09-30 05:07:28.177944 | controller | Tuesday 30 September 2025  05:07:27 +0000 (0:00:00.346)       0:02:31.775 *****
2025-09-30 05:07:28.177954 | controller | changed: [instance]
2025-09-30 05:07:28.518023 | controller |
2025-09-30 05:07:28.518055 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-09-30 05:07:28.518064 | controller | Tuesday 30 September 2025  05:07:28 +0000 (0:00:00.348)       0:02:32.124 *****
2025-09-30 05:07:28.518074 | controller | changed: [instance]
2025-09-30 05:07:28.862810 | controller |
2025-09-30 05:07:28.862842 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-09-30 05:07:28.862850 | controller | Tuesday 30 September 2025  05:07:28 +0000 (0:00:00.340)       0:02:32.464 *****
2025-09-30 05:07:28.862860 | controller | changed: [instance]
2025-09-30 05:07:29.216268 | controller |
2025-09-30 05:07:29.216303 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-09-30 05:07:29.216311 | controller | Tuesday 30 September 2025  05:07:28 +0000 (0:00:00.344)       0:02:32.808 *****
2025-09-30 05:07:29.216322 | controller | changed: [instance]
2025-09-30 05:07:29.575853 | controller |
2025-09-30 05:07:29.575887 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-09-30 05:07:29.575895 | controller | Tuesday 30 September 2025  05:07:29 +0000 (0:00:00.353)       0:02:33.162 *****
2025-09-30 05:07:29.575905 | controller | changed: [instance]
2025-09-30 05:07:29.914967 | controller |
2025-09-30 05:07:29.914998 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-09-30 05:07:29.915011 | controller | Tuesday 30 September 2025  05:07:29 +0000 (0:00:00.359)       0:02:33.522 *****
2025-09-30 05:07:29.915022 | controller | changed: [instance]
2025-09-30 05:07:30.255876 | controller |
2025-09-30 05:07:30.255905 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-09-30 05:07:30.255914 | controller | Tuesday 30 September 2025  05:07:29 +0000 (0:00:00.339)       0:02:33.861 *****
2025-09-30 05:07:30.255924 | controller | changed: [instance]
2025-09-30 05:07:30.590865 | controller |
2025-09-30 05:07:30.590895 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-09-30 05:07:30.590904 | controller | Tuesday 30 September 2025  05:07:30 +0000 (0:00:00.340)       0:02:34.201 *****
2025-09-30 05:07:30.590914 | controller | changed: [instance]
2025-09-30 05:07:31.931350 | controller |
2025-09-30 05:07:31.931379 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-09-30 05:07:31.931387 | controller | Tuesday 30 September 2025  05:07:30 +0000 (0:00:00.335)       0:02:34.536 *****
2025-09-30 05:07:31.931397 | controller | changed: [instance]
2025-09-30 05:07:32.262829 | controller |
2025-09-30 05:07:32.262861 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-09-30 05:07:32.262869 | controller | Tuesday 30 September 2025  05:07:31 +0000 (0:00:01.340)       0:02:35.877 *****
2025-09-30 05:07:32.262886 | controller | changed: [instance]
2025-09-30 05:07:32.593825 | controller |
2025-09-30 05:07:32.593862 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-09-30 05:07:32.593871 | controller | Tuesday 30 September 2025  05:07:32 +0000 (0:00:00.331)       0:02:36.208 *****
2025-09-30 05:07:32.593881 | controller | changed: [instance]
2025-09-30 05:07:32.931673 | controller |
2025-09-30 05:07:32.931704 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-09-30 05:07:32.931713 | controller | Tuesday 30 September 2025  05:07:32 +0000 (0:00:00.330)       0:02:36.539 *****
2025-09-30 05:07:32.931724 | controller | changed: [instance]
2025-09-30 05:07:32.950978 | controller |
2025-09-30 05:07:32.951001 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-09-30 05:07:32.951009 | controller | Tuesday 30 September 2025  05:07:32 +0000 (0:00:00.337)       0:02:36.877 *****
2025-09-30 05:07:32.951018 | controller | skipping: [instance]
2025-09-30 05:07:33.226823 | controller |
2025-09-30 05:07:33.226853 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-09-30 05:07:33.226862 | controller | Tuesday 30 September 2025  05:07:32 +0000 (0:00:00.019)       0:02:36.897 *****
2025-09-30 05:07:33.226871 | controller | ok: [instance]
2025-09-30 05:07:33.619296 | controller |
2025-09-30 05:07:33.619329 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-09-30 05:07:33.619338 | controller | Tuesday 30 September 2025  05:07:33 +0000 (0:00:00.275)       0:02:37.172 *****
2025-09-30 05:07:33.619348 | controller | changed: [instance]
2025-09-30 05:07:33.619763 | controller |
2025-09-30 05:07:33.927273 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-09-30 05:07:33.927303 | controller | Tuesday 30 September 2025  05:07:33 +0000 (0:00:00.392)       0:02:37.565 *****
2025-09-30 05:07:33.927315 | controller | changed: [instance]
2025-09-30 05:07:33.927338 | controller |
2025-09-30 05:07:33.927345 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-09-30 05:07:33.927352 | controller | Tuesday 30 September 2025  05:07:33 +0000 (0:00:00.307)       0:02:37.873 *****
2025-09-30 05:07:34.211868 | controller | [WARNING]: Reset is not implemented for this connection
2025-09-30 05:07:34.233392 | controller | changed: [instance]
2025-09-30 05:07:34.235289 | controller |
2025-09-30 05:07:34.235321 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-09-30 05:07:34.235330 | controller | Tuesday 30 September 2025  05:07:34 +0000 (0:00:00.279)       0:02:38.153 *****
2025-09-30 05:07:34.235341 | controller |
2025-09-30 05:07:34.235905 | controller | PLAY RECAP *********************************************************************
2025-09-30 05:07:34.235921 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-09-30 05:07:34.235929 | controller |
2025-09-30 05:07:34.235934 | controller | Tuesday 30 September 2025  05:07:34 +0000 (0:00:00.025)       0:02:38.179 *****
2025-09-30 05:07:34.235940 | controller | ===============================================================================
2025-09-30 05:07:34.235946 | controller | libvirt_manager : Install packages required for using KVM -------------- 76.03s
2025-09-30 05:07:34.235951 | controller | test_deps : Install selinux python libs -------------------------------- 44.76s
2025-09-30 05:07:34.235957 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.13s
2025-09-30 05:07:34.235967 | controller | Install some debug utils ------------------------------------------------ 4.42s
2025-09-30 05:07:34.235973 | controller | libvirt_manager : Ensure admin socket is enabled for storage. ----------- 1.34s
2025-09-30 05:07:34.235978 | controller | test_deps : Install python yaml libs ------------------------------------ 1.20s
2025-09-30 05:07:34.235983 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.20s
2025-09-30 05:07:34.235988 | controller | Gathering Facts --------------------------------------------------------- 0.92s
2025-09-30 05:07:34.235994 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.85s
2025-09-30 05:07:34.235999 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.85s
2025-09-30 05:07:34.236004 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.75s
2025-09-30 05:07:34.236014 | controller | repo_setup : Install repo-setup package --------------------------------- 0.74s
2025-09-30 05:07:34.236020 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.71s
2025-09-30 05:07:34.236028 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.70s
2025-09-30 05:07:34.299699 | controller | repo_setup : Ensure directories are present ----------------------------- 0.59s
2025-09-30 05:07:34.299733 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.58s
2025-09-30 05:07:34.299741 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.57s
2025-09-30 05:07:34.299747 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.45s
2025-09-30 05:07:34.299752 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.39s
2025-09-30 05:07:34.299758 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.38s
2025-09-30 05:07:34.299768 | controller | INFO     Running default > converge
2025-09-30 05:07:34.740521 | controller |
2025-09-30 05:07:34.740728 | controller | PLAY [Converge] ****************************************************************
2025-09-30 05:07:34.740869 | controller |
2025-09-30 05:07:34.741015 | controller | TASK [Gathering Facts] *********************************************************
2025-09-30 05:07:34.741156 | controller | Tuesday 30 September 2025  05:07:34 +0000 (0:00:00.013)       0:00:00.013 *****
2025-09-30 05:07:36.524281 | controller | ok: [instance]
2025-09-30 05:07:36.524446 | controller |
2025-09-30 05:07:36.524480 | controller | TASK [Crate SSH keypair] *******************************************************
2025-09-30 05:07:36.524495 | controller | Tuesday 30 September 2025  05:07:36 +0000 (0:00:01.783)       0:00:01.797 *****
2025-09-30 05:07:36.901275 | controller | changed: [instance]
2025-09-30 05:07:37.389256 | controller |
2025-09-30 05:07:37.389285 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-09-30 05:07:37.389294 | controller | Tuesday 30 September 2025  05:07:36 +0000 (0:00:00.376)       0:00:02.174 *****
2025-09-30 05:07:37.389304 | controller | changed: [instance]
2025-09-30 05:07:38.387513 | controller |
2025-09-30 05:07:38.387544 | controller | TASK [Restart firewalld.service] ***********************************************
2025-09-30 05:07:38.387553 | controller | Tuesday 30 September 2025  05:07:37 +0000 (0:00:00.487)       0:00:02.661 *****
2025-09-30 05:07:38.387563 | controller | changed: [instance]
2025-09-30 05:07:38.427218 | controller |
2025-09-30 05:07:38.427250 | controller | TASK [Discover latest image] ***************************************************
2025-09-30 05:07:38.427260 | controller | Tuesday 30 September 2025  05:07:38 +0000 (0:00:00.997)       0:00:03.659 *****
2025-09-30 05:07:38.427272 | controller |
2025-09-30 05:07:40.378152 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-09-30 05:07:40.378219 | controller | Tuesday 30 September 2025  05:07:38 +0000 (0:00:00.040)       0:00:03.700 *****
2025-09-30 05:07:40.378235 | controller | changed: [instance]
2025-09-30 05:07:40.404970 | controller |
2025-09-30 05:07:40.404998 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-09-30 05:07:40.405011 | controller | Tuesday 30 September 2025  05:07:40 +0000 (0:00:01.950)       0:00:05.651 *****
2025-09-30 05:07:40.405022 | controller | ok: [instance]
2025-09-30 05:07:59.749014 | controller |
2025-09-30 05:07:59.749047 | controller | TASK [Download latest image] ***************************************************
2025-09-30 05:07:59.749056 | controller | Tuesday 30 September 2025  05:07:40 +0000 (0:00:00.026)       0:00:05.677 *****
2025-09-30 05:07:59.749066 | controller | changed: [instance]
2025-09-30 05:07:59.788342 | controller |
2025-09-30 05:07:59.788378 | controller | TASK [Build nat64 appliance image] *********************************************
2025-09-30 05:07:59.788388 | controller | Tuesday 30 September 2025  05:07:59 +0000 (0:00:19.344)       0:00:25.021 *****
2025-09-30 05:07:59.788398 | controller |
2025-09-30 05:08:00.283267 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-09-30 05:08:00.283303 | controller | Tuesday 30 September 2025  05:07:59 +0000 (0:00:00.039)       0:00:25.061 *****
2025-09-30 05:08:00.283323 | controller | ok: [instance] => (item=artifacts)
2025-09-30 05:08:00.498282 | controller | ok: [instance] => (item=logs)
2025-09-30 05:08:00.498312 | controller |
2025-09-30 05:08:00.498321 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-09-30 05:08:00.498328 | controller | Tuesday 30 September 2025  05:08:00 +0000 (0:00:00.494)       0:00:25.555 *****
2025-09-30 05:08:00.498337 | controller | changed: [instance]
2025-09-30 05:08:04.921407 | controller |
2025-09-30 05:08:04.921440 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-09-30 05:08:04.921449 | controller | Tuesday 30 September 2025  05:08:00 +0000 (0:00:00.215)       0:00:25.771 *****
2025-09-30 05:08:04.921459 | controller | ok: [instance]
2025-09-30 05:08:13.267302 | controller |
2025-09-30 05:08:13.267335 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-09-30 05:08:13.267344 | controller | Tuesday 30 September 2025  05:08:04 +0000 (0:00:04.422)       0:00:30.193 *****
2025-09-30 05:08:13.267354 | controller | changed: [instance]
2025-09-30 05:08:13.267361 | controller |
2025-09-30 05:08:13.267367 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-09-30 05:08:13.267374 | controller | Tuesday 30 September 2025  05:08:13 +0000 (0:00:08.346)       0:00:38.540 *****
2025-09-30 05:08:23.193985 | controller | changed: [instance] => (item=elements/)
2025-09-30 05:08:24.366329 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-09-30 05:08:24.366359 | controller |
2025-09-30 05:08:24.366367 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-09-30 05:08:24.366373 | controller | Tuesday 30 September 2025  05:08:23 +0000 (0:00:09.926)       0:00:48.466 *****
2025-09-30 05:08:24.366383 | controller | changed: [instance]
2025-09-30 05:08:24.366406 | controller |
2025-09-30 05:08:24.366620 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-09-30 05:12:54.125306 | controller | Tuesday 30 September 2025  05:08:24 +0000 (0:00:01.172)       0:00:49.639 *****
2025-09-30 05:12:54.125586 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-09-30 05:12:54.340445 | controller | changed: [instance]
2025-09-30 05:12:54.340476 | controller |
2025-09-30 05:12:54.340485 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-09-30 05:12:54.340491 | controller | Tuesday 30 September 2025  05:12:54 +0000 (0:04:29.758)       0:05:19.397 *****
2025-09-30 05:12:54.340501 | controller | changed: [instance]
2025-09-30 05:13:01.718345 | controller |
2025-09-30 05:13:01.718380 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-09-30 05:13:01.718391 | controller | Tuesday 30 September 2025  05:12:54 +0000 (0:00:00.215)       0:05:19.613 *****
2025-09-30 05:13:01.718403 | controller | changed: [instance]
2025-09-30 05:13:01.764325 | controller |
2025-09-30 05:13:01.764361 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-09-30 05:13:01.764377 | controller | Tuesday 30 September 2025  05:13:01 +0000 (0:00:07.377)       0:05:26.991 *****
2025-09-30 05:13:01.764389 | controller |
2025-09-30 05:13:01.764419 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-09-30 05:13:01.819519 | controller | Tuesday 30 September 2025  05:13:01 +0000 (0:00:00.046)       0:05:27.037 *****
2025-09-30 05:13:01.819549 | controller | ok: [instance]
2025-09-30 05:13:02.571104 | controller |
2025-09-30 05:13:02.571134 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-09-30 05:13:02.571143 | controller | Tuesday 30 September 2025  05:13:01 +0000 (0:00:00.054)       0:05:27.092 *****
2025-09-30 05:13:02.571153 | controller | changed: [instance]
2025-09-30 05:13:02.876276 | controller |
2025-09-30 05:13:02.876307 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-09-30 05:13:02.876315 | controller | Tuesday 30 September 2025  05:13:02 +0000 (0:00:00.751)       0:05:27.843 *****
2025-09-30 05:13:02.876326 | controller | ok: [instance]
2025-09-30 05:13:02.876414 | controller |
2025-09-30 05:13:02.876447 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-09-30 05:13:02.876461 | controller | Tuesday 30 September 2025  05:13:02 +0000 (0:00:00.305)       0:05:28.149 *****
2025-09-30 05:13:03.100950 | controller | ok: [instance]
2025-09-30 05:13:03.326297 | controller |
2025-09-30 05:13:03.326328 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-09-30 05:13:03.326337 | controller | Tuesday 30 September 2025  05:13:03 +0000 (0:00:00.224)       0:05:28.373 *****
2025-09-30 05:13:03.326347 | controller | changed: [instance]
2025-09-30 05:13:03.326522 | controller |
2025-09-30 05:13:03.326534 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-09-30 05:13:03.326543 | controller | Tuesday 30 September 2025  05:13:03 +0000 (0:00:00.225)       0:05:28.599 *****
2025-09-30 05:13:03.558273 | controller | changed: [instance]
2025-09-30 05:13:03.801247 | controller |
2025-09-30 05:13:03.801276 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-09-30 05:13:03.801285 | controller | Tuesday 30 September 2025  05:13:03 +0000 (0:00:00.231)       0:05:28.831 *****
2025-09-30 05:13:03.801295 | controller | ok: [instance]
2025-09-30 05:13:04.022701 | controller |
2025-09-30 05:13:04.022730 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-09-30 05:13:04.022739 | controller | Tuesday 30 September 2025  05:13:03 +0000 (0:00:00.242)       0:05:29.074 *****
2025-09-30 05:13:04.022750 | controller | ok: [instance]
2025-09-30 05:13:04.247342 | controller |
2025-09-30 05:13:04.247373 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-09-30 05:13:04.247381 | controller | Tuesday 30 September 2025  05:13:04 +0000 (0:00:00.221)       0:05:29.295 *****
2025-09-30 05:13:04.247392 | controller | changed: [instance]
2025-09-30 05:13:05.018336 | controller |
2025-09-30 05:13:05.018366 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-09-30 05:13:05.018374 | controller | Tuesday 30 September 2025  05:13:04 +0000 (0:00:00.224)       0:05:29.520 *****
2025-09-30 05:13:05.018385 | controller | changed: [instance] => (item=br-64v6)
2025-09-30 05:13:05.869310 | controller | changed: [instance] => (item=br-64v4)
2025-09-30 05:13:05.869340 | controller |
2025-09-30 05:13:05.869348 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-09-30 05:13:05.869354 | controller | Tuesday 30 September 2025  05:13:05 +0000 (0:00:00.770)       0:05:30.291 *****
2025-09-30 05:13:05.869364 | controller | changed: [instance]
2025-09-30 05:13:05.869488 | controller |
2025-09-30 05:13:05.869499 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-09-30 05:13:05.869507 | controller | Tuesday 30 September 2025  05:13:05 +0000 (0:00:00.851)       0:05:31.142 *****
2025-09-30 05:13:05.900672 | controller | ok: [instance]
2025-09-30 05:13:05.937514 | controller |
2025-09-30 05:13:05.937543 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-09-30 05:13:05.937551 | controller | Tuesday 30 September 2025  05:13:05 +0000 (0:00:00.031)       0:05:31.173 *****
2025-09-30 05:13:05.937561 | controller |
2025-09-30 05:13:06.328523 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-09-30 05:13:06.328553 | controller | Tuesday 30 September 2025  05:13:05 +0000 (0:00:00.036)       0:05:31.210 *****
2025-09-30 05:13:06.328565 | controller | ok: [instance] => (item=artifacts)
2025-09-30 05:13:07.641021 | controller | ok: [instance] => (item=logs)
2025-09-30 05:13:07.641053 | controller |
2025-09-30 05:13:07.641061 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-09-30 05:13:07.641067 | controller | Tuesday 30 September 2025  05:13:06 +0000 (0:00:00.390)       0:05:31.600 *****
2025-09-30 05:13:07.641077 | controller | ok: [instance]
2025-09-30 05:13:07.848294 | controller |
2025-09-30 05:13:07.848326 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-09-30 05:13:07.848334 | controller | Tuesday 30 September 2025  05:13:07 +0000 (0:00:01.312)       0:05:32.913 *****
2025-09-30 05:13:07.848344 | controller | changed: [instance]
2025-09-30 05:13:08.206145 | controller |
2025-09-30 05:13:08.206176 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-09-30 05:13:08.206202 | controller | Tuesday 30 September 2025  05:13:07 +0000 (0:00:00.207)       0:05:33.120 *****
2025-09-30 05:13:08.206213 | controller | changed: [instance]
2025-09-30 05:13:08.600749 | controller |
2025-09-30 05:13:08.600779 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-09-30 05:13:08.600788 | controller | Tuesday 30 September 2025  05:13:08 +0000 (0:00:00.357)       0:05:33.478 *****
2025-09-30 05:13:08.600798 | controller | changed: [instance]
2025-09-30 05:13:08.987535 | controller |
2025-09-30 05:13:08.987566 | controller | TASK [config_drive : Generate network-data] ************************************
2025-09-30 05:13:08.987581 | controller | Tuesday 30 September 2025  05:13:08 +0000 (0:00:00.394)       0:05:33.873 *****
2025-09-30 05:13:08.987591 | controller | changed: [instance]
2025-09-30 05:13:09.177953 | controller |
2025-09-30 05:13:09.177983 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-09-30 05:13:09.177991 | controller | Tuesday 30 September 2025  05:13:08 +0000 (0:00:00.386)       0:05:34.260 *****
2025-09-30 05:13:09.178001 | controller | ok: [instance]
2025-09-30 05:13:09.196281 | controller |
2025-09-30 05:13:09.196308 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-09-30 05:13:09.196317 | controller | Tuesday 30 September 2025  05:13:09 +0000 (0:00:00.190)       0:05:34.450 *****
2025-09-30 05:13:09.196327 | controller | skipping: [instance]
2025-09-30 05:13:09.422701 | controller |
2025-09-30 05:13:09.422733 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-09-30 05:13:09.422741 | controller | Tuesday 30 September 2025  05:13:09 +0000 (0:00:00.018)       0:05:34.469 *****
2025-09-30 05:13:09.422751 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-09-30 05:13:10.554689 | controller | changed: [instance]
2025-09-30 05:13:10.554724 | controller |
2025-09-30 05:13:10.554734 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-09-30 05:13:10.554742 | controller | Tuesday 30 September 2025  05:13:09 +0000 (0:00:00.226)       0:05:34.695 *****
2025-09-30 05:13:10.554754 | controller | changed: [instance]
2025-09-30 05:13:11.476980 | controller |
2025-09-30 05:13:11.477038 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-09-30 05:13:11.477047 | controller | Tuesday 30 September 2025  05:13:10 +0000 (0:00:01.132)       0:05:35.827 *****
2025-09-30 05:13:11.477059 | controller | changed: [instance]
2025-09-30 05:13:11.505094 | controller |
2025-09-30 05:13:11.505128 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-09-30 05:13:11.505136 | controller | Tuesday 30 September 2025  05:13:11 +0000 (0:00:00.921)       0:05:36.749 *****
2025-09-30 05:13:11.505148 | controller | ok: [instance]
2025-09-30 05:13:11.551777 | controller |
2025-09-30 05:13:11.551821 | controller | TASK [Set MAC address facts] ***************************************************
2025-09-30 05:13:11.551830 | controller | Tuesday 30 September 2025  05:13:11 +0000 (0:00:00.028)       0:05:36.777 *****
2025-09-30 05:13:11.551841 | controller | ok: [instance]
2025-09-30 05:13:11.805366 | controller |
2025-09-30 05:13:11.805412 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-09-30 05:13:11.805421 | controller | Tuesday 30 September 2025  05:13:11 +0000 (0:00:00.046)       0:05:36.824 *****
2025-09-30 05:13:11.805433 | controller | changed: [instance]
2025-09-30 05:13:12.073473 | controller |
2025-09-30 05:13:12.073503 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-09-30 05:13:12.073511 | controller | Tuesday 30 September 2025  05:13:11 +0000 (0:00:00.253)       0:05:37.077 *****
2025-09-30 05:13:12.073521 | controller | ok: [instance]
2025-09-30 05:13:12.310029 | controller |
2025-09-30 05:13:12.310060 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-09-30 05:13:12.310068 | controller | Tuesday 30 September 2025  05:13:12 +0000 (0:00:00.268)       0:05:37.346 *****
2025-09-30 05:13:12.310079 | controller | ok: [instance]
2025-09-30 05:13:12.527399 | controller |
2025-09-30 05:13:12.527429 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-09-30 05:13:12.527438 | controller | Tuesday 30 September 2025  05:13:12 +0000 (0:00:00.234)       0:05:37.580 *****
2025-09-30 05:13:12.527449 | controller | changed: [instance]
2025-09-30 05:13:12.857903 | controller |
2025-09-30 05:13:12.857932 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-09-30 05:13:12.857947 | controller | Tuesday 30 September 2025  05:13:12 +0000 (0:00:00.219)       0:05:37.800 *****
2025-09-30 05:13:12.857957 | controller | changed: [instance]
2025-09-30 05:13:13.653422 | controller |
2025-09-30 05:13:13.653452 | controller | TASK [Restart firewalld.service] ***********************************************
2025-09-30 05:13:13.653460 | controller | Tuesday 30 September 2025  05:13:12 +0000 (0:00:00.330)       0:05:38.130 *****
2025-09-30 05:13:13.653471 | controller | changed: [instance]
2025-09-30 05:13:13.682744 | controller |
2025-09-30 05:13:13.682771 | controller | TASK [Generate test node UUID] *************************************************
2025-09-30 05:13:13.682779 | controller | Tuesday 30 September 2025  05:13:13 +0000 (0:00:00.794)       0:05:38.925 *****
2025-09-30 05:13:13.682790 | controller | ok: [instance]
2025-09-30 05:13:22.186921 | controller |
2025-09-30 05:13:22.186957 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-09-30 05:13:22.186966 | controller | Tuesday 30 September 2025  05:13:13 +0000 (0:00:00.030)       0:05:38.955 *****
2025-09-30 05:13:22.186982 | controller | changed: [instance]
2025-09-30 05:13:22.246009 | controller |
2025-09-30 05:13:22.246036 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-09-30 05:13:22.246044 | controller | Tuesday 30 September 2025  05:13:22 +0000 (0:00:08.503)       0:05:47.459 *****
2025-09-30 05:13:22.246064 | controller |
2025-09-30 05:13:22.699926 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-09-30 05:13:22.699960 | controller | Tuesday 30 September 2025  05:13:22 +0000 (0:00:00.057)       0:05:47.517 *****
2025-09-30 05:13:22.699971 | controller | ok: [instance] => (item=artifacts)
2025-09-30 05:13:23.945662 | controller | ok: [instance] => (item=logs)
2025-09-30 05:13:23.945697 | controller |
2025-09-30 05:13:23.945705 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-09-30 05:13:23.945711 | controller | Tuesday 30 September 2025  05:13:22 +0000 (0:00:00.455)       0:05:47.972 *****
2025-09-30 05:13:23.945722 | controller | ok: [instance]
2025-09-30 05:13:24.159637 | controller |
2025-09-30 05:13:24.159678 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-09-30 05:13:24.159686 | controller | Tuesday 30 September 2025  05:13:23 +0000 (0:00:01.243)       0:05:49.215 *****
2025-09-30 05:13:24.159696 | controller | changed: [instance]
2025-09-30 05:13:24.515854 | controller |
2025-09-30 05:13:24.515889 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-09-30 05:13:24.515897 | controller | Tuesday 30 September 2025  05:13:24 +0000 (0:00:00.216)       0:05:49.432 *****
2025-09-30 05:13:24.515908 | controller | changed: [instance]
2025-09-30 05:13:24.890162 | controller |
2025-09-30 05:13:24.890209 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-09-30 05:13:24.890220 | controller | Tuesday 30 September 2025  05:13:24 +0000 (0:00:00.356)       0:05:49.788 *****
2025-09-30 05:13:24.890231 | controller | changed: [instance]
2025-09-30 05:13:25.259292 | controller |
2025-09-30 05:13:25.259336 | controller | TASK [config_drive : Generate network-data] ************************************
2025-09-30 05:13:25.259344 | controller | Tuesday 30 September 2025  05:13:24 +0000 (0:00:00.374)       0:05:50.162 *****
2025-09-30 05:13:25.259355 | controller | changed: [instance]
2025-09-30 05:13:25.448845 | controller |
2025-09-30 05:13:25.448877 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-09-30 05:13:25.448888 | controller | Tuesday 30 September 2025  05:13:25 +0000 (0:00:00.369)       0:05:50.532 *****
2025-09-30 05:13:25.448901 | controller | ok: [instance]
2025-09-30 05:13:25.468590 | controller |
2025-09-30 05:13:25.468623 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-09-30 05:13:25.468632 | controller | Tuesday 30 September 2025  05:13:25 +0000 (0:00:00.186)       0:05:50.718 *****
2025-09-30 05:13:25.468643 | controller | skipping: [instance]
2025-09-30 05:13:25.709928 | controller |
2025-09-30 05:13:25.709959 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-09-30 05:13:25.709967 | controller | Tuesday 30 September 2025  05:13:25 +0000 (0:00:00.022)       0:05:50.741 *****
2025-09-30 05:13:25.709977 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-09-30 05:13:26.001081 | controller | changed: [instance]
2025-09-30 05:13:26.001126 | controller |
2025-09-30 05:13:26.001135 | controller | TASK [Define test-node VM] *****************************************************
2025-09-30 05:13:26.001141 | controller | Tuesday 30 September 2025  05:13:25 +0000 (0:00:00.241)       0:05:50.982 *****
2025-09-30 05:13:26.001151 | controller | changed: [instance]
2025-09-30 05:13:26.814318 | controller |
2025-09-30 05:13:26.814362 | controller | TASK [Start test-node VM] ******************************************************
2025-09-30 05:13:26.814371 | controller | Tuesday 30 September 2025  05:13:25 +0000 (0:00:00.291)       0:05:51.273 *****
2025-09-30 05:13:26.814381 | controller | changed: [instance]
2025-09-30 05:13:55.532056 | controller |
2025-09-30 05:13:55.532097 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-09-30 05:13:55.532106 | controller | Tuesday 30 September 2025  05:13:26 +0000 (0:00:00.813)       0:05:52.086 *****
2025-09-30 05:13:55.532115 | controller | ok: [instance]
2025-09-30 05:13:55.552277 | controller |
2025-09-30 05:13:55.552305 | controller | TASK [Add test node to inventory] **********************************************
2025-09-30 05:13:55.552314 | controller | Tuesday 30 September 2025  05:13:55 +0000 (0:00:28.717)       0:06:20.804 *****
2025-09-30 05:13:55.552324 | controller | changed: [instance]
2025-09-30 05:13:55.577661 | controller |
2025-09-30 05:13:55.577689 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-09-30 05:13:55.577697 | controller | Tuesday 30 September 2025  05:13:55 +0000 (0:00:00.020)       0:06:20.825 *****
2025-09-30 05:13:55.577707 | controller | changed: [instance]
2025-09-30 05:14:15.598310 | controller |
2025-09-30 05:14:15.598347 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-09-30 05:14:15.598385 | controller | Tuesday 30 September 2025  05:13:55 +0000 (0:00:00.023)       0:06:20.849 *****
2025-09-30 05:14:15.598397 | controller | Pausing for 20 seconds
2025-09-30 05:14:15.598423 | controller | ok: [instance]
2025-09-30 05:14:15.598431 | controller |
2025-09-30 05:14:15.598640 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-09-30 05:14:22.080870 | controller | Tuesday 30 September 2025  05:14:15 +0000 (0:00:20.022)       0:06:40.871 *****
2025-09-30 05:14:22.080905 | controller | changed: [instance]
2025-09-30 05:14:22.080963 | controller |
2025-09-30 05:14:22.080979 | controller | TASK [Grab some info from the test node] ***************************************
2025-09-30 05:14:22.080990 | controller | Tuesday 30 September 2025  05:14:22 +0000 (0:00:06.482)       0:06:47.353 *****
2025-09-30 05:14:23.159132 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-09-30 05:14:23.159200 | controller |
2025-09-30 05:14:23.159388 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-09-30 05:14:24.184289 | controller | Tuesday 30 September 2025  05:14:23 +0000 (0:00:01.078)       0:06:48.432 *****
2025-09-30 05:14:24.184335 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-09-30 05:14:24.184364 | controller |
2025-09-30 05:14:24.184373 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-09-30 05:14:24.184517 | controller | Tuesday 30 September 2025  05:14:24 +0000 (0:00:01.025)       0:06:49.457 *****
2025-09-30 05:14:24.820745 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-09-30 05:14:25.334332 | controller |
2025-09-30 05:14:25.334377 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-09-30 05:14:25.334387 | controller | Tuesday 30 September 2025  05:14:24 +0000 (0:00:00.636)       0:06:50.093 *****
2025-09-30 05:14:25.334400 | controller | changed: [instance]
2025-09-30 05:14:25.334429 | controller |
2025-09-30 05:14:25.334440 | controller | TASK [Write test-node info to file] ********************************************
2025-09-30 05:14:25.334539 | controller | Tuesday 30 September 2025  05:14:25 +0000 (0:00:00.513)       0:06:50.607 *****
2025-09-30 05:14:25.673972 | controller | changed: [instance]
2025-09-30 05:14:26.016467 | controller |
2025-09-30 05:14:26.016497 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-09-30 05:14:26.016505 | controller | Tuesday 30 September 2025  05:14:25 +0000 (0:00:00.339)       0:06:50.946 *****
2025-09-30 05:14:26.016516 | controller | changed: [instance]
2025-09-30 05:14:26.361056 | controller |
2025-09-30 05:14:26.361089 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-09-30 05:14:26.361097 | controller | Tuesday 30 September 2025  05:14:26 +0000 (0:00:00.342)       0:06:51.289 *****
2025-09-30 05:14:26.361107 | controller | changed: [instance]
2025-09-30 05:14:26.711089 | controller |
2025-09-30 05:14:26.711122 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-09-30 05:14:26.711130 | controller | Tuesday 30 September 2025  05:14:26 +0000 (0:00:00.344)       0:06:51.633 *****
2025-09-30 05:14:26.711141 | controller | changed: [instance]
2025-09-30 05:14:27.054492 | controller |
2025-09-30 05:14:27.054523 | controller | TASK [Write hypervisor info to file] *******************************************
2025-09-30 05:14:27.054531 | controller | Tuesday 30 September 2025  05:14:26 +0000 (0:00:00.350)       0:06:51.983 *****
2025-09-30 05:14:27.054541 | controller | changed: [instance]
2025-09-30 05:14:28.699645 | controller |
2025-09-30 05:14:28.699683 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-09-30 05:14:28.699692 | controller | Tuesday 30 September 2025  05:14:27 +0000 (0:00:00.343)       0:06:52.327 *****
2025-09-30 05:14:28.699702 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-09-30 05:14:28.742300 | controller |
2025-09-30 05:14:28.742339 | controller | TASK [Debug the ping example.com result] ***************************************
2025-09-30 05:14:28.742348 | controller | Tuesday 30 September 2025  05:14:28 +0000 (0:00:01.644)       0:06:53.972 *****
2025-09-30 05:14:28.742360 | controller | ok: [instance] => (item=0) =>
2025-09-30 05:14:28.742386 | controller |   msg: '0'
2025-09-30 05:14:28.745939 | controller | ok: [instance] => (item=['PING example.com(a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a)) 56 data bytes', '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=1 ttl=45 time=34.3 ms', '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=2 ttl=45 time=33.5 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1002ms', 'rtt min/avg/max/mdev = 33.520/33.885/34.251/0.365 ms']) =>
2025-09-30 05:14:28.809800 | controller |   msg:
2025-09-30 05:14:28.809833 | controller |   - PING example.com(a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a)) 56 data bytes
2025-09-30 05:14:28.809841 | controller |   - '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=1 ttl=45 time=34.3 ms'
2025-09-30 05:14:28.809846 | controller |   - '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=2 ttl=45 time=33.5 ms'
2025-09-30 05:14:28.809852 | controller |   - ''
2025-09-30 05:14:28.809857 | controller |   - '--- example.com ping statistics ---'
2025-09-30 05:14:28.809863 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1002ms
2025-09-30 05:14:28.809870 | controller |   - rtt min/avg/max/mdev = 33.520/33.885/34.251/0.365 ms
2025-09-30 05:14:28.809876 | controller | ok: [instance] => (item=[]) =>
2025-09-30 05:14:28.809881 | controller |   msg: []
2025-09-30 05:14:28.809887 | controller |
2025-09-30 05:14:28.809893 | controller | PLAY RECAP *********************************************************************
2025-09-30 05:14:28.809898 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-09-30 05:14:28.809903 | controller |
2025-09-30 05:14:28.809909 | controller | Tuesday 30 September 2025  05:14:28 +0000 (0:00:00.042)       0:06:54.015 *****
2025-09-30 05:14:28.809914 | controller | ===============================================================================
2025-09-30 05:14:28.809919 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 269.76s
2025-09-30 05:14:28.809924 | controller | Wait for test node to be reachable via ssh ----------------------------- 28.72s
2025-09-30 05:14:28.809930 | controller | Wait a little to let the test instance boot. --------------------------- 20.02s
2025-09-30 05:14:28.809946 | controller | Download latest image -------------------------------------------------- 19.34s
2025-09-30 05:14:28.809952 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir --------------- 9.93s
2025-09-30 05:14:28.809964 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.50s
2025-09-30 05:14:28.809970 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.35s
2025-09-30 05:14:28.809975 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.38s
2025-09-30 05:14:28.809980 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.48s
2025-09-30 05:14:28.809986 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.42s
2025-09-30 05:14:28.809991 | controller | discover_latest_image : Get latest image -------------------------------- 1.95s
2025-09-30 05:14:28.809996 | controller | Gathering Facts --------------------------------------------------------- 1.78s
2025-09-30 05:14:28.810002 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.64s
2025-09-30 05:14:28.810007 | controller | config_drive : Install required RPM packages ---------------------------- 1.31s
2025-09-30 05:14:28.810012 | controller | config_drive : Install required RPM packages ---------------------------- 1.24s
2025-09-30 05:14:28.810017 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.17s
2025-09-30 05:14:28.810023 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.13s
2025-09-30 05:14:28.810029 | controller | Grab some info from the test node --------------------------------------- 1.08s
2025-09-30 05:14:28.810034 | controller | Grab some info from the nat64 appliance --------------------------------- 1.03s
2025-09-30 05:14:28.810039 | controller | Restart firewalld.service ----------------------------------------------- 1.00s
2025-09-30 05:14:28.810050 | controller | INFO     Running default > cleanup
2025-09-30 05:14:29.285938 | controller |
2025-09-30 05:14:30.218225 | controller | PLAY [Cleanup] *****************************************************************
2025-09-30 05:14:30.218257 | controller |
2025-09-30 05:14:30.218265 | controller | TASK [Gathering Facts] *********************************************************
2025-09-30 05:14:30.218271 | controller | Tuesday 30 September 2025  05:14:29 +0000 (0:00:00.054)       0:00:00.054 *****
2025-09-30 05:14:30.218281 | controller | ok: [instance]
2025-09-30 05:14:30.788208 | controller |
2025-09-30 05:14:30.788239 | controller | TASK [Destroy the test-node] ***************************************************
2025-09-30 05:14:30.788247 | controller | Tuesday 30 September 2025  05:14:30 +0000 (0:00:00.933)       0:00:00.987 *****
2025-09-30 05:14:30.788258 | controller | ok: [instance]
2025-09-30 05:14:31.031681 | controller |
2025-09-30 05:14:31.031714 | controller | TASK [Undefine the test-node] **************************************************
2025-09-30 05:14:31.031723 | controller | Tuesday 30 September 2025  05:14:30 +0000 (0:00:00.569)       0:00:01.557 *****
2025-09-30 05:14:31.031733 | controller | ok: [instance]
2025-09-30 05:14:31.397861 | controller |
2025-09-30 05:14:31.397891 | controller | TASK [Destroy the test network] ************************************************
2025-09-30 05:14:31.397899 | controller | Tuesday 30 September 2025  05:14:31 +0000 (0:00:00.243)       0:00:01.800 *****
2025-09-30 05:14:31.397909 | controller | ok: [instance]
2025-09-30 05:14:31.614313 | controller |
2025-09-30 05:14:31.614357 | controller | TASK [Undefine the test network] ***********************************************
2025-09-30 05:14:31.614366 | controller | Tuesday 30 September 2025  05:14:31 +0000 (0:00:00.366)       0:00:02.167 *****
2025-09-30 05:14:31.614376 | controller | ok: [instance]
2025-09-30 05:14:31.614403 | controller |
2025-09-30 05:14:31.614410 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-09-30 05:14:31.614417 | controller | Tuesday 30 September 2025  05:14:31 +0000 (0:00:00.216)       0:00:02.383 *****
2025-09-30 05:14:31.645285 | controller |
2025-09-30 05:14:31.645395 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-09-30 05:14:31.645426 | controller | Tuesday 30 September 2025  05:14:31 +0000 (0:00:00.031)       0:00:02.414 *****
2025-09-30 05:14:31.936819 | controller | changed: [instance]
2025-09-30 05:14:32.208163 | controller |
2025-09-30 05:14:32.208246 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-09-30 05:14:32.208256 | controller | Tuesday 30 September 2025  05:14:31 +0000 (0:00:00.291)       0:00:02.706 *****
2025-09-30 05:14:32.208271 | controller | ok: [instance]
2025-09-30 05:14:32.447359 | controller |
2025-09-30 05:14:32.447393 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-09-30 05:14:32.447401 | controller | Tuesday 30 September 2025  05:14:32 +0000 (0:00:00.271)       0:00:02.977 *****
2025-09-30 05:14:32.447411 | controller | ok: [instance]
2025-09-30 05:14:32.447436 | controller |
2025-09-30 05:14:32.447444 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-09-30 05:14:32.447528 | controller | Tuesday 30 September 2025  05:14:32 +0000 (0:00:00.239)       0:00:03.216 *****
2025-09-30 05:14:33.128274 | controller | ok: [instance]
2025-09-30 05:14:33.128685 | controller |
2025-09-30 05:14:33.369291 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-09-30 05:14:33.369325 | controller | Tuesday 30 September 2025  05:14:33 +0000 (0:00:00.680)       0:00:03.897 *****
2025-09-30 05:14:33.369338 | controller | ok: [instance]
2025-09-30 05:14:33.369626 | controller |
2025-09-30 05:14:33.369651 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-09-30 05:14:34.162263 | controller | Tuesday 30 September 2025  05:14:33 +0000 (0:00:00.241)       0:00:04.138 *****
2025-09-30 05:14:34.162301 | controller | ok: [instance] => (item=nat64-net-v4)
2025-09-30 05:14:34.162328 | controller | ok: [instance] => (item=nat64-net-v6)
2025-09-30 05:14:34.162335 | controller |
2025-09-30 05:14:34.162343 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-09-30 05:14:34.162492 | controller | Tuesday 30 September 2025  05:14:34 +0000 (0:00:00.792)       0:00:04.931 *****
2025-09-30 05:14:34.633280 | controller | ok: [instance] => (item=nat64-net-v4)
2025-09-30 05:14:34.633641 | controller | ok: [instance] => (item=nat64-net-v6)
2025-09-30 05:14:34.633657 | controller |
2025-09-30 05:14:34.633664 | controller | PLAY RECAP *********************************************************************
2025-09-30 05:14:34.633670 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-09-30 05:14:34.633676 | controller |
2025-09-30 05:14:34.633681 | controller | Tuesday 30 September 2025  05:14:34 +0000 (0:00:00.469)       0:00:05.401 *****
2025-09-30 05:14:34.633687 | controller | ===============================================================================
2025-09-30 05:14:34.633692 | controller | Gathering Facts --------------------------------------------------------- 0.93s
2025-09-30 05:14:34.633698 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.79s
2025-09-30 05:14:34.633703 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.68s
2025-09-30 05:14:34.633708 | controller | Destroy the test-node --------------------------------------------------- 0.57s
2025-09-30 05:14:34.633714 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.47s
2025-09-30 05:14:34.633719 | controller | Destroy the test network ------------------------------------------------ 0.37s
2025-09-30 05:14:34.633724 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.29s
2025-09-30 05:14:34.633730 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.27s
2025-09-30 05:14:34.633735 | controller | Undefine the test-node -------------------------------------------------- 0.24s
2025-09-30 05:14:34.633740 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.24s
2025-09-30 05:14:34.633749 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.24s
2025-09-30 05:14:34.682408 | controller | Undefine the test network ----------------------------------------------- 0.22s
2025-09-30 05:14:34.682440 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-09-30 05:14:34.682452 | controller | INFO     Writing /tmp/report.html report.
2025-09-30 05:14:35.055768 | [controller] Waiting on logger
2025-09-30 05:14:40.242568 | [controller] Waiting on logger
2025-09-30 05:14:50.674332 | [controller] Waiting on logger
2025-09-30 05:15:00.054852 | [controller] Waiting on logger
2025-09-30 05:15:04.761941 | [Zuul] Log Stream did not terminate
2025-09-30 05:15:04.762124 | controller | changed
2025-09-30 05:15:04.787691 | 
2025-09-30 05:15:04.787785 | PLAY RECAP
2025-09-30 05:15:04.787828 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 05:15:04.787852 | 
2025-09-30 05:15:04.873281 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-30 05:15:04.874311 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-30 05:15:05.499669 | 
2025-09-30 05:15:05.499837 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-09-30 05:15:05.540545 | 
2025-09-30 05:15:05.540641 | TASK [Filter out host if needed]
2025-09-30 05:15:05.553821 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-09-30 05:15:05.558409 | 
2025-09-30 05:15:05.558481 | TASK [Ensure file is present]
2025-09-30 05:15:05.896216 | controller | ok
2025-09-30 05:15:05.904241 | 
2025-09-30 05:15:05.904311 | TASK [Manage molecule report file]
2025-09-30 05:15:05.954018 | [controller] Waiting on logger
2025-09-30 05:15:15.314338 | [controller] Waiting on logger
2025-09-30 05:15:25.746390 | [controller] Waiting on logger
2025-09-30 05:15:35.126870 | [controller] Waiting on logger
2025-09-30 05:15:36.319387 | [Zuul] Log Stream did not terminate
2025-09-30 05:15:36.319572 | controller | changed
2025-09-30 05:15:36.325058 | 
2025-09-30 05:15:36.325132 | TASK [Check if we get ci-framework-data basedir]
2025-09-30 05:15:36.519670 | controller | ok
2025-09-30 05:15:36.525949 | 
2025-09-30 05:15:36.526057 | TASK [Create ci-framework-data log directory for zuul]
2025-09-30 05:15:36.847558 | controller | changed
2025-09-30 05:15:36.853215 | 
2025-09-30 05:15:36.853297 | TASK [Copy ci-framework interesting files]
2025-09-30 05:15:41.883527 | controller | changed
2025-09-30 05:15:41.888984 | 
2025-09-30 05:15:41.889073 | TASK [Get SELinux listing]
2025-09-30 05:15:41.910984 | [controller] Waiting on logger
2025-09-30 05:15:51.218455 | [controller] Waiting on logger
2025-09-30 05:16:01.650408 | [controller] Waiting on logger
2025-09-30 05:16:12.082356 | [controller] Waiting on logger
2025-09-30 05:16:12.112899 | [Zuul] Log Stream did not terminate
2025-09-30 05:16:12.113091 | controller | changed
2025-09-30 05:16:12.118703 | 
2025-09-30 05:16:12.118769 | TASK [Generate log index]
2025-09-30 05:16:12.739872 | controller | changed
2025-09-30 05:16:12.745212 | 
2025-09-30 05:16:12.745290 | TASK [Get some env related data]
2025-09-30 05:16:17.772200 | controller | changed
2025-09-30 05:16:17.778407 | 
2025-09-30 05:16:17.778473 | TASK [Generate list of logs to collect in home directory]
2025-09-30 05:16:18.090948 | controller | ok: All paths examined
2025-09-30 05:16:18.096487 | 
2025-09-30 05:16:18.096568 | LOOP [Copy logs from home directory]
2025-09-30 05:16:18.436393 | controller | changed:
2025-09-30 05:16:18.436527 | controller | {
2025-09-30 05:16:18.436556 | controller |   "atime": 1759208657.4753807,
2025-09-30 05:16:18.436577 | controller |   "ctime": 1759208675.6823456,
2025-09-30 05:16:18.436595 | controller |   "dev": 64513,
2025-09-30 05:16:18.436613 | controller |   "gid": 1000,
2025-09-30 05:16:18.436629 | controller |   "gr_name": "zuul",
2025-09-30 05:16:18.436662 | controller |   "inode": 4331459,
2025-09-30 05:16:18.436679 | controller |   "isblk": false,
2025-09-30 05:16:18.436695 | controller |   "ischr": false,
2025-09-30 05:16:18.436710 | controller |   "isdir": false,
2025-09-30 05:16:18.436725 | controller |   "isfifo": false,
2025-09-30 05:16:18.436740 | controller |   "isgid": false,
2025-09-30 05:16:18.436756 | controller |   "islnk": false,
2025-09-30 05:16:18.436771 | controller |   "isreg": true,
2025-09-30 05:16:18.436786 | controller |   "issock": false,
2025-09-30 05:16:18.436802 | controller |   "isuid": false,
2025-09-30 05:16:18.436817 | controller |   "mode": "0644",
2025-09-30 05:16:18.436832 | controller |   "mtime": 1759208675.6823456,
2025-09-30 05:16:18.436847 | controller |   "nlink": 1,
2025-09-30 05:16:18.436861 | controller |   "path": "/home/zuul/ansible.log",
2025-09-30 05:16:18.436879 | controller |   "pw_name": "zuul",
2025-09-30 05:16:18.436894 | controller |   "rgrp": true,
2025-09-30 05:16:18.436931 | controller |   "roth": true,
2025-09-30 05:16:18.436953 | controller |   "rusr": true,
2025-09-30 05:16:18.436970 | controller |   "size": 6749,
2025-09-30 05:16:18.436985 | controller |   "uid": 1000,
2025-09-30 05:16:18.437001 | controller |   "wgrp": false,
2025-09-30 05:16:18.437015 | controller |   "woth": false,
2025-09-30 05:16:18.437031 | controller |   "wusr": true,
2025-09-30 05:16:18.437046 | controller |   "xgrp": false,
2025-09-30 05:16:18.437063 | controller |   "xoth": false,
2025-09-30 05:16:18.437078 | controller |   "xusr": false
2025-09-30 05:16:18.437094 | controller | }
2025-09-30 05:16:18.450900 | 
2025-09-30 05:16:18.450983 | TASK [Copy crio stats log file]
2025-09-30 05:16:18.464294 | controller | skipping: Conditional result was False
2025-09-30 05:16:18.470819 | 
2025-09-30 05:16:18.470904 | TASK [Get SELinux related data]
2025-09-30 05:16:18.493543 | [controller] Waiting on logger
2025-09-30 05:16:22.514428 | [controller] Waiting on logger
2025-09-30 05:16:23.602286 | controller | ERROR
2025-09-30 05:16:23.602492 | controller | {
2025-09-30 05:16:23.602524 | controller |   "delta": "0:00:00.008511",
2025-09-30 05:16:23.602549 | controller |   "end": "2025-09-30 05:16:18.681516",
2025-09-30 05:16:23.602568 | controller |   "msg": "non-zero return code",
2025-09-30 05:16:23.602586 | controller |   "rc": 1,
2025-09-30 05:16:23.602606 | controller |   "start": "2025-09-30 05:16:18.673005"
2025-09-30 05:16:23.602624 | controller | }
2025-09-30 05:16:23.602665 | controller | ERROR: Ignoring Errors
2025-09-30 05:16:23.609103 | 
2025-09-30 05:16:23.609167 | TASK [Create system configuration directory]
2025-09-30 05:16:23.840089 | controller | changed
2025-09-30 05:16:23.845054 | 
2025-09-30 05:16:23.845134 | TASK [Get some of the system configurations]
2025-09-30 05:16:28.894151 | controller | changed
2025-09-30 05:16:28.899886 | 
2025-09-30 05:16:28.899979 | TASK [Copy generated documentation if available]
2025-09-30 05:16:28.913846 | controller | skipping: Conditional result was False
2025-09-30 05:16:28.920516 | 
2025-09-30 05:16:28.920597 | TASK [Copy generated AsciiDoc documentation if available]
2025-09-30 05:16:28.953292 | controller | skipping: Conditional result was False
2025-09-30 05:16:28.959800 | 
2025-09-30 05:16:28.959877 | TASK [Compress logs bigger than 2MB]
2025-09-30 05:16:32.946408 | [controller] Waiting on logger
2025-09-30 05:16:33.989175 | controller | changed
2025-09-30 05:16:33.994604 | 
2025-09-30 05:16:33.994681 | TASK [Copy files from workspace on node]
2025-09-30 05:16:34.013480 | controller | ok
2025-09-30 05:16:34.057335 | 
2025-09-30 05:16:34.057419 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 05:16:34.081125 | controller | skipping: Conditional result was False
2025-09-30 05:16:34.086845 | 
2025-09-30 05:16:34.086937 | TASK [fetch-output : Set log path for single node]
2025-09-30 05:16:34.134484 | controller | ok
2025-09-30 05:16:34.140046 | 
2025-09-30 05:16:34.140112 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 05:16:34.391092 | controller -> localhost | ok: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/logs"
2025-09-30 05:16:34.391368 | controller -> localhost | changed: All items complete
2025-09-30 05:16:34.391401 | 
2025-09-30 05:16:34.597859 | controller -> localhost | changed: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/artifacts"
2025-09-30 05:16:34.804542 | controller -> localhost | changed: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/docs"
2025-09-30 05:16:34.815299 | 
2025-09-30 05:16:34.815407 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 05:16:35.497340 | controller | changed:
2025-09-30 05:16:35.497579 | controller | .d..t...... ./
2025-09-30 05:16:35.497619 | controller | >f+++++++++ README.html
2025-09-30 05:16:35.497645 | controller | >f+++++++++ ansible-execution.log
2025-09-30 05:16:35.497683 | controller | >f+++++++++ ansible.log
2025-09-30 05:16:35.497704 | controller | >f+++++++++ dmesg.log
2025-09-30 05:16:35.497723 | controller | >f+++++++++ installed-pkgs.log
2025-09-30 05:16:35.497741 | controller | >f+++++++++ python.log
2025-09-30 05:16:35.497758 | controller | >f+++++++++ registries.conf
2025-09-30 05:16:35.497775 | controller | >f+++++++++ report.html
2025-09-30 05:16:35.497791 | controller | >f+++++++++ selinux-denials.log
2025-09-30 05:16:35.497807 | controller | >f+++++++++ selinux-listing.log
2025-09-30 05:16:35.497823 | controller | cd+++++++++ ci-framework-data/
2025-09-30 05:16:35.497841 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-09-30 05:16:35.497858 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-09-30 05:16:35.497876 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-09-30 05:16:35.497893 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-09-30 05:16:35.497930 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-09-30 05:16:35.497954 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-09-30 05:16:35.497973 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/08df5533-399f-5b51-9390-3769568c7d55/
2025-09-30 05:16:35.497991 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/08df5533-399f-5b51-9390-3769568c7d55/meta-data
2025-09-30 05:16:35.498008 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/08df5533-399f-5b51-9390-3769568c7d55/network-config
2025-09-30 05:16:35.498025 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/08df5533-399f-5b51-9390-3769568c7d55/user-data
2025-09-30 05:16:35.498041 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/ea555e97-7072-5fe5-86a2-76d894324357/
2025-09-30 05:16:35.498057 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/ea555e97-7072-5fe5-86a2-76d894324357/meta-data
2025-09-30 05:16:35.498073 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/ea555e97-7072-5fe5-86a2-76d894324357/network-config
2025-09-30 05:16:35.498088 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/ea555e97-7072-5fe5-86a2-76d894324357/user-data
2025-09-30 05:16:35.498111 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-09-30 05:16:35.498129 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-09-30 05:16:35.498145 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-09-30 05:16:35.498162 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-09-30 05:16:35.498178 | controller | cd+++++++++ ci-framework-data/logs/
2025-09-30 05:16:35.498193 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-09-30 05:16:35.498210 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-09-30 05:16:35.498226 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-09-30 05:16:35.498242 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-09-30 05:16:35.498257 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-09-30 05:16:35.498273 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-09-30 05:16:35.498288 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-09-30 05:16:35.498304 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-09-30 05:16:35.498319 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-09-30 05:16:35.498336 | controller | cd+++++++++ registries.conf.d/
2025-09-30 05:16:35.498351 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-09-30 05:16:35.498367 | controller | cd+++++++++ system-config/
2025-09-30 05:16:35.498382 | controller | cd+++++++++ system-config/libvirt/
2025-09-30 05:16:35.498398 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-09-30 05:16:35.498413 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-09-30 05:16:35.498429 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-09-30 05:16:35.498445 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-09-30 05:16:35.498461 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-09-30 05:16:35.498477 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-09-30 05:16:35.498492 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-09-30 05:16:35.498507 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-09-30 05:16:35.498522 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-09-30 05:16:35.498537 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-09-30 05:16:35.498552 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-09-30 05:16:35.498567 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-09-30 05:16:35.498581 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-09-30 05:16:35.498596 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-09-30 05:16:35.498611 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-09-30 05:16:35.498626 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-09-30 05:16:36.242439 | controller | changed: .d..t...... ./
2025-09-30 05:16:36.737419 | controller | changed: .d..t...... ./
2025-09-30 05:16:36.759677 | 
2025-09-30 05:16:36.759766 | TASK [Return artifact to Zuul]
2025-09-30 05:16:36.805031 | controller | ok
2025-09-30 05:16:36.825126 | 
2025-09-30 05:16:36.825202 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-09-30 05:16:36.825306 | 
2025-09-30 05:16:36.825333 | PLAY RECAP
2025-09-30 05:16:36.825371 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-09-30 05:16:36.825393 | 
2025-09-30 05:16:36.928183 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-30 05:16:36.928969 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 05:16:37.713565 | 
2025-09-30 05:16:37.713730 | PLAY [all]
2025-09-30 05:16:37.742825 | 
2025-09-30 05:16:37.742941 | TASK [include_role : fetch-output]
2025-09-30 05:16:37.802269 | controller | ok
2025-09-30 05:16:37.835412 | 
2025-09-30 05:16:37.835534 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 05:16:37.934203 | controller | skipping: Conditional result was False
2025-09-30 05:16:37.940109 | 
2025-09-30 05:16:37.940201 | TASK [fetch-output : Set log path for single node]
2025-09-30 05:16:37.989695 | controller | ok
2025-09-30 05:16:37.995410 | 
2025-09-30 05:16:37.995499 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 05:16:38.586745 | controller -> localhost | ok: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/logs"
2025-09-30 05:16:38.904146 | controller -> localhost | ok: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/artifacts"
2025-09-30 05:16:39.099264 | controller -> localhost | ok: "/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/docs"
2025-09-30 05:16:39.108945 | 
2025-09-30 05:16:39.109056 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 05:16:39.693162 | controller | ok
2025-09-30 05:16:39.693376 | controller | ok: All items complete
2025-09-30 05:16:39.693407 | 
2025-09-30 05:16:40.168174 | controller | ok
2025-09-30 05:16:40.633294 | controller | ok
2025-09-30 05:16:40.653885 | 
2025-09-30 05:16:40.654017 | TASK [include_role : fetch-output-openshift]
2025-09-30 05:16:40.667450 | controller | skipping: Conditional result was False
2025-09-30 05:16:40.673657 | 
2025-09-30 05:16:40.673748 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 05:16:41.055511 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006339
2025-09-30 05:16:41.305211 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.025001
2025-09-30 05:16:41.338383 | 
2025-09-30 05:16:41.338473 | PLAY [all]
2025-09-30 05:16:41.353222 | 
2025-09-30 05:16:41.353294 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-30 05:16:41.800885 | controller | changed
2025-09-30 05:16:41.831850 | 
2025-09-30 05:16:41.831954 | PLAY RECAP
2025-09-30 05:16:41.832003 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 05:16:41.832029 | 
2025-09-30 05:16:41.926543 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 05:16:41.927340 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-30 05:16:42.560832 | 
2025-09-30 05:16:42.560952 | PLAY [localhost]
2025-09-30 05:16:42.579089 | 
2025-09-30 05:16:42.579166 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 05:16:43.014781 | localhost | changed
2025-09-30 05:16:43.019416 | 
2025-09-30 05:16:43.019495 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 05:16:43.047328 | localhost | ok
2025-09-30 05:16:43.055079 | 
2025-09-30 05:16:43.055148 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-30 05:16:43.418210 | localhost | changed
2025-09-30 05:16:43.424230 | 
2025-09-30 05:16:43.424325 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-30 05:16:44.225923 | localhost | changed
2025-09-30 05:16:44.230973 | 
2025-09-30 05:16:44.231056 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-30 05:16:44.682932 | localhost | Identity added: /var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/tmp/ansible.zqjbaxg5 (/var/lib/zuul/builds/5f2f0fc6adde475cbb7e8a43812a991d/work/tmp/ansible.zqjbaxg5)
2025-09-30 05:16:44.683107 | localhost | ok: Runtime: 0:00:00.007237
2025-09-30 05:16:44.687422 | 
2025-09-30 05:16:44.687491 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-30 05:16:44.908722 | localhost | ok: Runtime: 0:00:00.003689
2025-09-30 05:16:44.914030 | 
2025-09-30 05:16:44.914110 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-30 05:16:44.961929 | localhost | changed
2025-09-30 05:16:44.966204 | 
2025-09-30 05:16:44.966275 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-30 05:16:45.297534 | localhost | changed
2025-09-30 05:16:45.317601 | 
2025-09-30 05:16:45.317675 | PLAY [localhost]
2025-09-30 05:16:45.329830 | 
2025-09-30 05:16:45.329891 | TASK [Generate bulk log download script]
2025-09-30 05:16:45.348029 | localhost | ok
2025-09-30 05:16:45.359622 | 
2025-09-30 05:16:45.359773 | TASK [local-log-download : Check API endpoint is defined]
2025-09-30 05:16:45.387618 | localhost | ok: All assertions passed
2025-09-30 05:16:45.392137 | 
2025-09-30 05:16:45.392202 | TASK [local-log-download : Create download script]
2025-09-30 05:16:45.760630 | localhost -> localhost | changed
2025-09-30 05:16:45.770389 | 
2025-09-30 05:16:45.770467 | TASK [Register quick-download link]
2025-09-30 05:16:45.789287 | localhost | ok
2025-09-30 05:16:45.826558 | 
2025-09-30 05:16:45.826652 | PLAY [logserver.rdoproject.org]
2025-09-30 05:16:45.836675 | 
2025-09-30 05:16:45.836738 | TASK [Set zuul-log-path fact]
2025-09-30 05:16:45.852988 | logserver.rdoproject.org | ok
2025-09-30 05:16:45.862228 | 
2025-09-30 05:16:45.862299 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 05:16:45.888621 | logserver.rdoproject.org | ok
2025-09-30 05:16:45.894384 | 
2025-09-30 05:16:45.894451 | TASK [upload-logs : Create log directories]
2025-09-30 05:16:47.512423 | logserver.rdoproject.org | changed
2025-09-30 05:16:47.515421 | 
2025-09-30 05:16:47.515482 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-30 05:16:47.752561 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004988
2025-09-30 05:16:47.757105 | 
2025-09-30 05:16:47.757170 | TASK [upload-logs : Upload logs to log server]
2025-09-30 05:16:49.398802 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-30 05:16:49.405959 | 
2025-09-30 05:16:49.406198 | LOOP [upload-logs : Compress console log and json output]
2025-09-30 05:16:49.450569 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:16:49.460150 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:16:49.469208 | 
2025-09-30 05:16:49.469289 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-30 05:16:49.506816 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:16:49.507055 | 
2025-09-30 05:16:49.510557 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:16:49.516389 | 
2025-09-30 05:16:49.516459 | LOOP [upload-logs : Upload console log and json output]