2025-09-29 18:50:36.472511 | Job console starting...
2025-09-29 18:50:36.710094 | Updating repositories
2025-09-29 18:50:37.547343 | Preparing job workspace
2025-09-29 18:50:56.653302 | Running Ansible setup...
2025-09-29 18:51:07.878945 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-29 18:51:10.736420 | 
2025-09-29 18:51:10.736534 | PLAY [localhost]
2025-09-29 18:51:10.793560 | 
2025-09-29 18:51:10.793745 | TASK [Gathering Facts]
2025-09-29 18:51:13.863561 | localhost | ok
2025-09-29 18:51:13.907114 | 
2025-09-29 18:51:13.907235 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-29 18:51:16.024083 | localhost -> localhost | changed
2025-09-29 18:51:16.029627 | 
2025-09-29 18:51:16.029719 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-29 18:51:20.141963 | localhost -> localhost | changed
2025-09-29 18:51:20.150694 | 
2025-09-29 18:51:20.150790 | TASK [Setup log path fact]
2025-09-29 18:51:20.225219 | localhost | ok
2025-09-29 18:51:20.286405 | 
2025-09-29 18:51:20.286513 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-29 18:51:20.388332 | localhost | ok
2025-09-29 18:51:20.409848 | 
2025-09-29 18:51:20.409966 | TASK [emit-job-header : Print job information]
2025-09-29 18:51:20.523367 | # Job Information
2025-09-29 18:51:20.523615 | Ansible Version: 2.15.12
2025-09-29 18:51:20.523648 | Job: cifmw-molecule-nat64_appliance
2025-09-29 18:51:20.523673 | Pipeline: github-check
2025-09-29 18:51:20.523695 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-09-29 18:51:20.523714 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333
2025-09-29 18:51:20.523735 | Log URL (when completed): https://logserver.rdoproject.org/54a/rdoproject.org/54a012b4e558421e80af7bc3266b63ac/
2025-09-29 18:51:20.523754 | Event ID: e4caed00-9d64-11f0-91c5-1ab1a6168f94
2025-09-29 18:51:20.527761 | 
2025-09-29 18:51:20.527836 | LOOP [emit-job-header : Print node information]
2025-09-29 18:51:21.000950 | localhost | ok:
2025-09-29 18:51:21.001154 | localhost | # Node Information
2025-09-29 18:51:21.001189 | localhost | Inventory Hostname: controller
2025-09-29 18:51:21.001215 | localhost | Hostname: np0005460581
2025-09-29 18:51:21.001237 | localhost | Username: zuul
2025-09-29 18:51:21.001259 | localhost | Distro: CentOS 9
2025-09-29 18:51:21.001279 | localhost | Provider: ibm-bm4-nodepool
2025-09-29 18:51:21.001298 | localhost | Region: regionOne
2025-09-29 18:51:21.001316 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-09-29 18:51:21.001334 | localhost | Product Name: OpenStack Compute
2025-09-29 18:51:21.001350 | localhost | Interface IP: 192.168.26.207
2025-09-29 18:51:21.111160 | 
2025-09-29 18:51:21.111262 | PLAY [all]
2025-09-29 18:51:21.143055 | 
2025-09-29 18:51:21.143139 | TASK [Gather network facts]
2025-09-29 18:51:21.621404 | controller | ok
2025-09-29 18:51:21.686933 | 
2025-09-29 18:51:21.687046 | TASK [include_role : start-zuul-console]
2025-09-29 18:51:21.770278 | controller | ok
2025-09-29 18:51:21.807973 | 
2025-09-29 18:51:21.808070 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-29 18:51:22.899126 | controller | ok
2025-09-29 18:51:22.914471 | 
2025-09-29 18:51:22.918628 | TASK [include_role : add-build-sshkey]
2025-09-29 18:51:22.987691 | controller | ok
2025-09-29 18:51:23.051283 | 
2025-09-29 18:51:23.051399 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-29 18:51:24.229577 | controller -> localhost | ok
2025-09-29 18:51:24.235273 | 
2025-09-29 18:51:24.235337 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-29 18:51:24.298100 | controller | ok
2025-09-29 18:51:24.347568 | controller | included: /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-29 18:51:24.377663 | 
2025-09-29 18:51:24.377779 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-29 18:51:27.974328 | controller -> localhost | Generating public/private rsa key pair.
2025-09-29 18:51:27.974529 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/54a012b4e558421e80af7bc3266b63ac_id_rsa.
2025-09-29 18:51:27.974565 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/54a012b4e558421e80af7bc3266b63ac_id_rsa.pub.
2025-09-29 18:51:27.974606 | controller -> localhost | The key fingerprint is:
2025-09-29 18:51:27.974631 | controller -> localhost | SHA256:nA3HHxinEFu2XMTjQHFzqvBmJ3mSYUSLX4vabBQHKd8 zuul-build-sshkey
2025-09-29 18:51:27.974653 | controller -> localhost | The key's randomart image is:
2025-09-29 18:51:27.974673 | controller -> localhost | +---[RSA 3072]----+
2025-09-29 18:51:27.974693 | controller -> localhost | |        o+X=* .  |
2025-09-29 18:51:27.974713 | controller -> localhost | |        .Xo@o+   |
2025-09-29 18:51:27.974732 | controller -> localhost | |        =o%+=.   |
2025-09-29 18:51:27.974750 | controller -> localhost | |       . X.@Eo   |
2025-09-29 18:51:27.974769 | controller -> localhost | |        S # =    |
2025-09-29 18:51:27.974788 | controller -> localhost | |         B =     |
2025-09-29 18:51:27.974806 | controller -> localhost | |        . +      |
2025-09-29 18:51:27.974827 | controller -> localhost | |         .       |
2025-09-29 18:51:27.974846 | controller -> localhost | |                 |
2025-09-29 18:51:27.974865 | controller -> localhost | +----[SHA256]-----+
2025-09-29 18:51:27.974925 | controller -> localhost | ok: Runtime: 0:00:01.647022
2025-09-29 18:51:27.980942 | 
2025-09-29 18:51:27.981008 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-29 18:51:28.047786 | controller | ok
2025-09-29 18:51:28.072313 | controller | included: /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-29 18:51:28.135741 | 
2025-09-29 18:51:28.135851 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-29 18:51:28.207373 | controller | skipping: Conditional result was False
2025-09-29 18:51:28.213600 | 
2025-09-29 18:51:28.213674 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-29 18:51:28.870600 | controller | changed
2025-09-29 18:51:28.877349 | 
2025-09-29 18:51:28.877417 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-29 18:51:29.183066 | controller | ok
2025-09-29 18:51:29.193062 | 
2025-09-29 18:51:29.193191 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-29 18:51:30.054650 | controller | changed
2025-09-29 18:51:30.066148 | 
2025-09-29 18:51:30.066250 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-29 18:51:30.829196 | controller | changed
2025-09-29 18:51:30.834530 | 
2025-09-29 18:51:30.834626 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-29 18:51:30.890777 | controller | skipping: Conditional result was False
2025-09-29 18:51:30.897321 | 
2025-09-29 18:51:30.897439 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-29 18:51:32.317788 | controller -> localhost | changed
2025-09-29 18:51:32.343642 | 
2025-09-29 18:51:32.343733 | TASK [add-build-sshkey : Add back temp key]
2025-09-29 18:51:33.347559 | controller -> localhost | Identity added: /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/54a012b4e558421e80af7bc3266b63ac_id_rsa (zuul-build-sshkey)
2025-09-29 18:51:33.347790 | controller -> localhost | ok: Runtime: 0:00:00.036640
2025-09-29 18:51:33.362227 | 
2025-09-29 18:51:33.362345 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-29 18:51:33.882240 | controller | ok
2025-09-29 18:51:33.897453 | 
2025-09-29 18:51:33.897524 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-29 18:51:33.989807 | controller | skipping: Conditional result was False
2025-09-29 18:51:34.008479 | 
2025-09-29 18:51:34.008568 | TASK [include_role : validate-host]
2025-09-29 18:51:34.074685 | controller | ok
2025-09-29 18:51:34.148814 | 
2025-09-29 18:51:34.148934 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-29 18:51:34.247481 | controller | ok
2025-09-29 18:51:34.255710 | 
2025-09-29 18:51:34.255796 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-29 18:51:35.320571 | controller -> localhost | ok
2025-09-29 18:51:35.326450 | 
2025-09-29 18:51:35.326530 | TASK [validate-host : Collect information about the host]
2025-09-29 18:51:36.018378 | controller | ok
2025-09-29 18:51:36.042761 | 
2025-09-29 18:51:36.042890 | TASK [validate-host : Sanitize hostname]
2025-09-29 18:51:36.213795 | controller | ok
2025-09-29 18:51:36.218904 | 
2025-09-29 18:51:36.218997 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-29 18:51:37.708429 | controller -> localhost | changed
2025-09-29 18:51:37.715976 | 
2025-09-29 18:51:37.716085 | TASK [validate-host : Collect information about zuul worker]
2025-09-29 18:51:38.757435 | controller | ok
2025-09-29 18:51:38.765192 | 
2025-09-29 18:51:38.765263 | TASK [validate-host : Write out all zuul information for each host]
2025-09-29 18:51:40.065329 | controller -> localhost | changed
2025-09-29 18:51:40.082121 | 
2025-09-29 18:51:40.082226 | TASK [include_role : prepare-workspace-openshift]
2025-09-29 18:51:40.140902 | controller | skipping: Conditional result was False
2025-09-29 18:51:40.146950 | 
2025-09-29 18:51:40.147035 | TASK [include_role : remove-zuul-sshkey]
2025-09-29 18:51:40.160534 | controller | skipping: Conditional result was False
2025-09-29 18:51:40.166747 | 
2025-09-29 18:51:40.166827 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-29 18:51:40.359687 | controller | ok: "logs"
2025-09-29 18:51:40.359887 | controller | ok: All items complete
2025-09-29 18:51:40.359936 | 
2025-09-29 18:51:40.555345 | controller | ok: "artifacts"
2025-09-29 18:51:40.726898 | controller | ok: "docs"
2025-09-29 18:51:40.734191 | 
2025-09-29 18:51:40.734279 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-29 18:51:41.000207 | controller | changed: "logs"
2025-09-29 18:51:41.188811 | controller | changed: "artifacts"
2025-09-29 18:51:41.392121 | controller | changed: "docs"
2025-09-29 18:51:41.446339 | 
2025-09-29 18:51:41.446429 | PLAY RECAP
2025-09-29 18:51:41.446473 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-29 18:51:41.446502 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-29 18:51:41.446522 | 
2025-09-29 18:51:41.680620 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-29 18:51:41.681370 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-29 18:51:43.084541 | 
2025-09-29 18:51:43.084681 | PLAY [all]
2025-09-29 18:51:43.155556 | 
2025-09-29 18:51:43.160108 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-29 18:51:43.320721 | controller | ok
2025-09-29 18:51:43.325810 | 
2025-09-29 18:51:43.325890 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-29 18:51:43.902278 | controller | changed
2025-09-29 18:51:43.908881 | 
2025-09-29 18:51:43.908996 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-29 18:51:45.305598 | controller | changed
2025-09-29 18:51:45.332394 | 
2025-09-29 18:51:45.332493 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-09-29 18:51:45.968433 | controller | changed:
2025-09-29 18:51:45.968604 | controller | {
2025-09-29 18:51:45.968638 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-09-29 18:51:45.968673 | controller | }
2025-09-29 18:51:46.177859 | controller | changed:
2025-09-29 18:51:46.177960 | controller | {
2025-09-29 18:51:46.177994 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-09-29 18:51:46.178019 | controller | }
2025-09-29 18:51:46.375184 | controller | changed:
2025-09-29 18:51:46.375264 | controller | {
2025-09-29 18:51:46.375292 | 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-29 18:51:46.375315 | controller | }
2025-09-29 18:51:46.584326 | controller | changed:
2025-09-29 18:51:46.584413 | controller | {
2025-09-29 18:51:46.584442 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-09-29 18:51:46.584464 | controller | }
2025-09-29 18:51:46.796343 | controller | changed:
2025-09-29 18:51:46.796416 | controller | {
2025-09-29 18:51:46.796543 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-09-29 18:51:46.796647 | controller | }
2025-09-29 18:51:47.003043 | controller | changed:
2025-09-29 18:51:47.003131 | controller | {
2025-09-29 18:51:47.003161 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-09-29 18:51:47.003184 | controller | }
2025-09-29 18:51:47.213855 | controller | changed:
2025-09-29 18:51:47.213954 | controller | {
2025-09-29 18:51:47.213986 | 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-29 18:51:47.214010 | controller | }
2025-09-29 18:51:47.446930 | controller | changed:
2025-09-29 18:51:47.447005 | controller | {
2025-09-29 18:51:47.447031 | 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-29 18:51:47.447052 | controller | }
2025-09-29 18:51:47.669542 | controller | changed:
2025-09-29 18:51:47.669645 | controller | {
2025-09-29 18:51:47.669674 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-09-29 18:51:47.669760 | controller | }
2025-09-29 18:51:47.925602 | controller | changed:
2025-09-29 18:51:47.925686 | controller | {
2025-09-29 18:51:47.925714 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-09-29 18:51:47.925736 | controller | }
2025-09-29 18:51:48.116517 | controller | changed:
2025-09-29 18:51:48.116623 | controller | {
2025-09-29 18:51:48.116652 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-09-29 18:51:48.116673 | controller | }
2025-09-29 18:51:48.343795 | controller | changed:
2025-09-29 18:51:48.343890 | controller | {
2025-09-29 18:51:48.343937 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-09-29 18:51:48.343964 | controller | }
2025-09-29 18:51:48.558988 | controller | changed:
2025-09-29 18:51:48.559080 | controller | {
2025-09-29 18:51:48.559109 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-09-29 18:51:48.559132 | controller | }
2025-09-29 18:51:48.772427 | controller | changed:
2025-09-29 18:51:48.772517 | controller | {
2025-09-29 18:51:48.772545 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-09-29 18:51:48.772565 | controller | }
2025-09-29 18:51:48.984515 | controller | changed:
2025-09-29 18:51:48.984623 | controller | {
2025-09-29 18:51:48.984652 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-09-29 18:51:48.984674 | controller | }
2025-09-29 18:51:49.210108 | controller | changed:
2025-09-29 18:51:49.210199 | controller | {
2025-09-29 18:51:49.210229 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-09-29 18:51:49.210252 | controller | }
2025-09-29 18:51:49.417690 | controller | changed:
2025-09-29 18:51:49.417799 | controller | {
2025-09-29 18:51:49.417828 | 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-29 18:51:49.417851 | controller | }
2025-09-29 18:51:49.626278 | controller | changed:
2025-09-29 18:51:49.626374 | controller | {
2025-09-29 18:51:49.626402 | 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-29 18:51:49.626432 | controller | }
2025-09-29 18:51:49.836420 | controller | changed:
2025-09-29 18:51:49.836578 | controller | {
2025-09-29 18:51:49.836612 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-09-29 18:51:49.836634 | controller | }
2025-09-29 18:51:50.052162 | controller | changed:
2025-09-29 18:51:50.052251 | controller | {
2025-09-29 18:51:50.052278 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-09-29 18:51:50.052300 | controller | }
2025-09-29 18:51:50.276791 | controller | changed:
2025-09-29 18:51:50.276873 | controller | {
2025-09-29 18:51:50.276904 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-09-29 18:51:50.276969 | controller | }
2025-09-29 18:51:50.507878 | controller | changed:
2025-09-29 18:51:50.507998 | controller | {
2025-09-29 18:51:50.508027 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-09-29 18:51:50.508055 | controller | }
2025-09-29 18:51:50.723302 | controller | changed:
2025-09-29 18:51:50.723398 | controller | {
2025-09-29 18:51:50.723428 | 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-29 18:51:50.723451 | controller | }
2025-09-29 18:51:50.936627 | controller | changed:
2025-09-29 18:51:50.936756 | controller | {
2025-09-29 18:51:50.936787 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-09-29 18:51:50.936809 | controller | }
2025-09-29 18:51:51.191273 | controller | changed:
2025-09-29 18:51:51.191352 | controller | {
2025-09-29 18:51:51.191381 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-09-29 18:51:51.191403 | controller | }
2025-09-29 18:51:51.387640 | controller | changed:
2025-09-29 18:51:51.387730 | controller | {
2025-09-29 18:51:51.387757 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-09-29 18:51:51.387777 | controller | }
2025-09-29 18:51:51.410387 | 
2025-09-29 18:51:51.410478 | TASK [Set timezone to UTC]
2025-09-29 18:51:51.891709 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-09-29 18:51:51.896696 | 
2025-09-29 18:51:51.896769 | TASK [Create nodepool directory]
2025-09-29 18:51:52.100191 | controller | changed
2025-09-29 18:51:52.108875 | 
2025-09-29 18:51:52.108980 | TASK [Create nodepool sub_nodes file]
2025-09-29 18:51:52.611483 | controller | changed
2025-09-29 18:51:52.617322 | 
2025-09-29 18:51:52.617402 | TASK [Create nodepool sub_nodes_private file]
2025-09-29 18:51:53.101854 | controller | changed
2025-09-29 18:51:53.107624 | 
2025-09-29 18:51:53.107740 | LOOP [Populate nodepool sub_nodes file]
2025-09-29 18:51:53.137263 | 
2025-09-29 18:51:53.137405 | LOOP [Populate nodepool sub_nodes_private file]
2025-09-29 18:51:53.166663 | 
2025-09-29 18:51:53.166820 | TASK [Create nodepool primary file]
2025-09-29 18:51:53.190871 | controller | skipping: Conditional result was False
2025-09-29 18:51:53.197120 | 
2025-09-29 18:51:53.197208 | TASK [Create nodepool node_private for this node]
2025-09-29 18:51:53.735377 | controller | changed
2025-09-29 18:51:53.740809 | 
2025-09-29 18:51:53.740891 | LOOP [Copy ssh keys to nodepool directory]
2025-09-29 18:51:54.079721 | controller | ok: Item: id_rsa Runtime: 0:00:00.005136
2025-09-29 18:51:54.079927 | 
2025-09-29 18:51:54.238104 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.004091
2025-09-29 18:51:54.247196 | 
2025-09-29 18:51:54.247290 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-09-29 18:51:54.806537 | controller | changed
2025-09-29 18:51:54.812213 | 
2025-09-29 18:51:54.812294 | TASK [Validate sudoers config after edits]
2025-09-29 18:51:55.050164 | controller | /etc/sudoers: parsed OK
2025-09-29 18:51:55.050249 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-09-29 18:51:55.050260 | controller | /etc/sudoers.d/zuul: parsed OK
2025-09-29 18:51:55.050267 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-09-29 18:51:55.350056 | controller | ok: Runtime: 0:00:00.005328
2025-09-29 18:51:55.357199 | 
2025-09-29 18:51:55.357286 | TASK [Show the environment passed in to job shell scripts]
2025-09-29 18:51:55.580156 | controller | SHELL=/bin/bash
2025-09-29 18:51:55.580213 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-09-29 18:51:55.580223 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-09-29 18:51:55.580230 | 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-29 18:51:55.580239 | controller | PWD=/home/zuul
2025-09-29 18:51:55.580244 | controller | ZUUL_PIPELINE=github-check
2025-09-29 18:51:55.580300 | controller | LOGNAME=zuul
2025-09-29 18:51:55.580309 | controller | XDG_SESSION_TYPE=tty
2025-09-29 18:51:55.580315 | controller | _=/usr/bin/env
2025-09-29 18:51:55.580320 | controller | MOTD_SHOWN=pam
2025-09-29 18:51:55.580326 | controller | HOME=/home/zuul
2025-09-29 18:51:55.580331 | controller | LANG=en_US.UTF-8
2025-09-29 18:51:55.580336 | controller | SSH_CONNECTION=192.168.26.12 60372 192.168.26.207 22
2025-09-29 18:51:55.580342 | 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-29 18:51:55.580348 | controller | ZUUL_CHANGE_IDS=3346,eb5b53fb17db92a72d33d052a56c8edd0d10ea78 3333,b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-29 18:51:55.580353 | controller | WORKSPACE=/home/zuul/workspace
2025-09-29 18:51:55.580359 | controller | XDG_SESSION_CLASS=user
2025-09-29 18:51:55.580364 | controller | SELINUX_ROLE_REQUESTED=
2025-09-29 18:51:55.580369 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-09-29 18:51:55.580375 | controller | USER=zuul
2025-09-29 18:51:55.580380 | controller | ZUUL_VOTING=True
2025-09-29 18:51:55.580385 | controller | BUILD_TIMEOUT=1800000
2025-09-29 18:51:55.580390 | controller | SELINUX_USE_CURRENT_RANGE=
2025-09-29 18:51:55.580396 | controller | SHLVL=1
2025-09-29 18:51:55.580401 | controller | ZUUL_PATCHSET=b461fc761ffaeed72eedc04b84a1fb92d251fe5d
2025-09-29 18:51:55.580407 | controller | XDG_SESSION_ID=1
2025-09-29 18:51:55.580412 | controller | ZUUL_BRANCH=main
2025-09-29 18:51:55.580417 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-09-29 18:51:55.580422 | controller | SSH_CLIENT=192.168.26.12 60372 22
2025-09-29 18:51:55.580428 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-09-29 18:51:55.580433 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-09-29 18:51:55.580439 | controller | which_declare=declare -f
2025-09-29 18:51:55.580444 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-09-29 18:51:55.580450 | controller | SELINUX_LEVEL_REQUESTED=
2025-09-29 18:51:55.580456 | controller | ZUUL_CHANGE=3333
2025-09-29 18:51:55.580473 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-09-29 18:51:55.580479 | controller | ZUUL_UUID=54a012b4e558421e80af7bc3266b63ac
2025-09-29 18:51:55.580484 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-09-29 18:51:55.580489 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-09-29 18:51:55.580495 | controller | }
2025-09-29 18:51:55.885945 | controller | ok: Runtime: 0:00:00.005953
2025-09-29 18:51:55.892219 | 
2025-09-29 18:51:55.892286 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-09-29 18:51:55.926116 | controller | skipping: Conditional result was False
2025-09-29 18:51:55.933379 | 
2025-09-29 18:51:55.933451 | TASK [Symlink /home/zuul-worker/workspace]
2025-09-29 18:51:56.469062 | controller | skipping: Conditional result was False
2025-09-29 18:51:56.474825 | 
2025-09-29 18:51:56.474894 | TASK [Ensure legacy workspace directory]
2025-09-29 18:51:56.659547 | controller | changed
2025-09-29 18:51:56.679792 | 
2025-09-29 18:51:56.679920 | PLAY RECAP
2025-09-29 18:51:56.679981 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-29 18:51:56.680008 | 
2025-09-29 18:51:56.781796 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-09-29 18:51:56.782623 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/read_global_vars.yml@main]
2025-09-29 18:51:57.376777 | 
2025-09-29 18:51:57.376890 | PLAY [Load global variables]
2025-09-29 18:51:57.400345 | 
2025-09-29 18:51:57.400458 | TASK [Read group_vars all file]
2025-09-29 18:51:57.430410 | controller | ok
2025-09-29 18:51:57.446440 | 
2025-09-29 18:51:57.446528 | TASK [cifmw_helpers : Check if file is available]
2025-09-29 18:51:57.718368 | controller | ok
2025-09-29 18:51:57.724513 | 
2025-09-29 18:51:57.724605 | TASK [cifmw_helpers : Read vars]
2025-09-29 18:51:57.743724 | 
2025-09-29 18:51:57.743854 | LOOP [cifmw_helpers : Set vars as fact]
2025-09-29 18:51:57.802716 | 
2025-09-29 18:51:57.802842 | PLAY RECAP
2025-09-29 18:51:57.802888 | controller | ok: 1 changed: 0 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-29 18:51:57.802952 | 
2025-09-29 18:51:57.891775 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/read_global_vars.yml@main]
2025-09-29 18:51:57.892552 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-29 18:51:58.510744 | 
2025-09-29 18:51:58.510848 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-09-29 18:51:58.531832 | 
2025-09-29 18:51:58.531922 | TASK [Create zuul-output directory]
2025-09-29 18:51:58.925679 | controller | changed
2025-09-29 18:51:58.930883 | 
2025-09-29 18:51:58.930997 | TASK [Slurp Zuul inventory test]
2025-09-29 18:51:59.248712 | controller -> localhost | ok
2025-09-29 18:51:59.255294 | 
2025-09-29 18:51:59.255382 | TASK [Save zuul inventory]
2025-09-29 18:52:00.060587 | controller | changed
2025-09-29 18:52:00.065655 | 
2025-09-29 18:52:00.065723 | TASK [Save zuul vars without the change_message]
2025-09-29 18:52:00.666523 | controller | changed
2025-09-29 18:52:00.697428 | 
2025-09-29 18:52:00.697499 | PLAY RECAP
2025-09-29 18:52:00.697543 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-29 18:52:00.697582 | 
2025-09-29 18:52:00.820394 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-09-29 18:52:00.821212 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-29 18:52:01.392796 | 
2025-09-29 18:52:01.392904 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-09-29 18:52:01.413629 | 
2025-09-29 18:52:01.413706 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-09-29 18:52:01.432565 | controller | ok
2025-09-29 18:52:01.449574 | 
2025-09-29 18:52:01.449664 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-09-29 18:52:01.473392 | controller | skipping: Conditional result was False
2025-09-29 18:52:01.479037 | 
2025-09-29 18:52:01.479113 | TASK [mirror-info-fork : Create /etc/ci]
2025-09-29 18:52:01.812162 | controller | ok
2025-09-29 18:52:01.818252 | 
2025-09-29 18:52:01.818324 | TASK [mirror-info-fork : Install ci_mirror script]
2025-09-29 18:52:02.428373 | controller | ok
2025-09-29 18:52:02.439605 | 
2025-09-29 18:52:02.439698 | TASK [Prepare workspace]
2025-09-29 18:52:02.460115 | controller | ok
2025-09-29 18:52:02.490461 | 
2025-09-29 18:52:02.490590 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-29 18:52:02.788680 | controller | ok
2025-09-29 18:52:02.797995 | 
2025-09-29 18:52:02.798092 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-29 18:52:05.459785 | controller | Output suppressed because no_log was given
2025-09-29 18:52:05.469233 | 
2025-09-29 18:52:05.469294 | LOOP [Create zuul-output directory]
2025-09-29 18:52:05.697797 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-09-29 18:52:05.862102 | controller | ok: "/home/zuul/zuul-output/logs"
2025-09-29 18:52:05.877427 | 
2025-09-29 18:52:05.877514 | TASK [Install required packages]
2025-09-29 18:52:55.278954 | controller | changed
2025-09-29 18:52:55.284203 | 
2025-09-29 18:52:55.284271 | TASK [Install venv]
2025-09-29 18:54:02.582544 | controller | changed
2025-09-29 18:54:02.608220 | 
2025-09-29 18:54:02.608303 | PLAY RECAP
2025-09-29 18:54:02.608349 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-29 18:54:02.608373 | 
2025-09-29 18:54:02.691844 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-09-29 18:54:02.692696 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-29 18:54:03.269189 | 
2025-09-29 18:54:03.269300 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-09-29 18:54:03.292270 | 
2025-09-29 18:54:03.292366 | TASK [Gather required facts]
2025-09-29 18:54:03.791279 | controller | ok
2025-09-29 18:54:03.796697 | 
2025-09-29 18:54:03.796789 | TASK [Load environment var if instructed to]
2025-09-29 18:54:03.820495 | controller | skipping: Conditional result was False
2025-09-29 18:54:03.826153 | 
2025-09-29 18:54:03.826227 | TASK [Run molecule]
2025-09-29 18:54:04.790666 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-09-29 18:54:04.859769 | controller | INFO     Performing prerun with role_name_check=0...
2025-09-29 18:54:21.524810 | 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-29 18:54:21.525295 | 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-29 18:54:21.525760 | 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-29 18:54:21.526246 | 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-29 18:54:21.526726 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+4a832a0b was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+4a832a0b (/home/zuul/.ansible/collections/ansible_collections).
2025-09-29 18:54:21.527210 | 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-29 18:54:21.527657 | 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-29 18:54:21.528123 | 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-29 18:54:21.528572 | 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-29 18:54:21.529011 | 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-29 18:54:21.529505 | 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-29 18:54:21.529953 | 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-29 18:54:21.530563 | 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-29 18:54:21.531014 | 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-29 18:54:21.531499 | 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-29 18:54:21.541065 | controller | INFO     Running default > prepare
2025-09-29 18:54:22.214245 | controller |
2025-09-29 18:54:22.214306 | controller | PLAY [Prepare] *****************************************************************
2025-09-29 18:54:22.214416 | controller |
2025-09-29 18:54:22.214520 | controller | TASK [Gathering Facts] *********************************************************
2025-09-29 18:54:22.214624 | controller | Monday 29 September 2025  18:54:22 +0000 (0:00:00.020)       0:00:00.020 ******
2025-09-29 18:54:23.024805 | controller | ok: [instance]
2025-09-29 18:54:23.024866 | controller |
2025-09-29 18:54:23.024986 | controller | TASK [Create custom basedir] ***************************************************
2025-09-29 18:54:23.025123 | controller | Monday 29 September 2025  18:54:23 +0000 (0:00:00.811)       0:00:00.831 ******
2025-09-29 18:54:23.339568 | controller | ok: [instance]
2025-09-29 18:54:23.339629 | controller |
2025-09-29 18:54:23.339743 | controller | TASK [Install some debug utils] ************************************************
2025-09-29 18:54:23.339841 | controller | Monday 29 September 2025  18:54:23 +0000 (0:00:00.314)       0:00:01.145 ******
2025-09-29 18:54:27.365387 | controller | changed: [instance]
2025-09-29 18:54:27.365437 | controller |
2025-09-29 18:54:27.365557 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-09-29 18:54:27.365668 | controller | Monday 29 September 2025  18:54:27 +0000 (0:00:04.025)       0:00:05.171 ******
2025-09-29 18:54:27.382867 | controller | skipping: [instance]
2025-09-29 18:54:27.382944 | controller |
2025-09-29 18:54:27.383048 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-09-29 18:54:27.383185 | controller | Monday 29 September 2025  18:54:27 +0000 (0:00:00.017)       0:00:05.189 ******
2025-09-29 18:54:27.423108 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-09-29 18:54:27.423165 | controller |
2025-09-29 18:54:27.423283 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-09-29 18:54:27.423390 | controller | Monday 29 September 2025  18:54:27 +0000 (0:00:00.040)       0:00:05.229 ******
2025-09-29 18:54:27.706484 | controller | ok: [instance]
2025-09-29 18:54:27.706538 | controller |
2025-09-29 18:54:27.706650 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-09-29 18:54:27.706753 | controller | Monday 29 September 2025  18:54:27 +0000 (0:00:00.283)       0:00:05.513 ******
2025-09-29 18:54:27.913455 | controller | ok: [instance]
2025-09-29 18:54:27.913530 | controller |
2025-09-29 18:54:27.913638 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-09-29 18:54:27.913747 | controller | Monday 29 September 2025  18:54:27 +0000 (0:00:00.206)       0:00:05.719 ******
2025-09-29 18:54:28.627001 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-09-29 18:54:28.627749 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-09-29 18:54:28.687831 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-09-29 18:54:28.687899 | controller |
2025-09-29 18:54:28.687908 | controller | TASK [Deploy repo-setup] *******************************************************
2025-09-29 18:54:28.687916 | controller | Monday 29 September 2025  18:54:28 +0000 (0:00:00.712)       0:00:06.432 ******
2025-09-29 18:54:28.687931 | controller |
2025-09-29 18:54:29.262152 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-09-29 18:54:29.262183 | controller | Monday 29 September 2025  18:54:28 +0000 (0:00:00.060)       0:00:06.493 ******
2025-09-29 18:54:29.262194 | controller | changed: [instance] => (item=tmp)
2025-09-29 18:54:29.917920 | controller | changed: [instance] => (item=artifacts/repositories)
2025-09-29 18:54:29.917950 | controller | changed: [instance] => (item=venv/repo_setup)
2025-09-29 18:54:29.917959 | controller |
2025-09-29 18:54:29.917971 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-09-29 18:54:29.917979 | controller | Monday 29 September 2025  18:54:29 +0000 (0:00:00.574)       0:00:07.068 ******
2025-09-29 18:54:29.917989 | controller | ok: [instance]
2025-09-29 18:54:31.074817 | controller |
2025-09-29 18:54:31.074856 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-09-29 18:54:31.074864 | controller | Monday 29 September 2025  18:54:29 +0000 (0:00:00.655)       0:00:07.724 ******
2025-09-29 18:54:31.074874 | controller | changed: [instance]
2025-09-29 18:54:39.029145 | controller |
2025-09-29 18:54:39.029219 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-09-29 18:54:39.029228 | controller | Monday 29 September 2025  18:54:31 +0000 (0:00:01.156)       0:00:08.880 ******
2025-09-29 18:54:39.029240 | controller | changed: [instance]
2025-09-29 18:54:39.745499 | controller |
2025-09-29 18:54:39.745541 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-09-29 18:54:39.745552 | controller | Monday 29 September 2025  18:54:39 +0000 (0:00:07.954)       0:00:16.835 ******
2025-09-29 18:54:39.745566 | controller | changed: [instance]
2025-09-29 18:54:39.767798 | controller |
2025-09-29 18:54:39.767837 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-09-29 18:54:39.767847 | controller | Monday 29 September 2025  18:54:39 +0000 (0:00:00.716)       0:00:17.551 ******
2025-09-29 18:54:39.767860 | controller | skipping: [instance]
2025-09-29 18:54:40.599152 | controller |
2025-09-29 18:54:40.599193 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-09-29 18:54:40.599202 | controller | Monday 29 September 2025  18:54:39 +0000 (0:00:00.022)       0:00:17.573 ******
2025-09-29 18:54:40.599213 | controller | changed: [instance]
2025-09-29 18:54:40.637268 | controller |
2025-09-29 18:54:40.637314 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-09-29 18:54:40.637323 | controller | Monday 29 September 2025  18:54:40 +0000 (0:00:00.831)       0:00:18.404 ******
2025-09-29 18:54:40.637335 | controller | skipping: [instance]
2025-09-29 18:54:40.675559 | controller |
2025-09-29 18:54:40.675597 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-09-29 18:54:40.675607 | controller | Monday 29 September 2025  18:54:40 +0000 (0:00:00.038)       0:00:18.443 ******
2025-09-29 18:54:40.675618 | controller | skipping: [instance]
2025-09-29 18:54:40.714131 | controller |
2025-09-29 18:54:40.714176 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-09-29 18:54:40.714184 | controller | Monday 29 September 2025  18:54:40 +0000 (0:00:00.038)       0:00:18.481 ******
2025-09-29 18:54:40.714195 | controller | skipping: [instance]
2025-09-29 18:54:41.305334 | controller |
2025-09-29 18:54:41.305378 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-09-29 18:54:41.305388 | controller | Monday 29 September 2025  18:54:40 +0000 (0:00:00.038)       0:00:18.520 ******
2025-09-29 18:54:41.305399 | controller | changed: [instance]
2025-09-29 18:54:41.750899 | controller |
2025-09-29 18:54:41.750929 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-09-29 18:54:41.750937 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.591)       0:00:19.111 ******
2025-09-29 18:54:41.750951 | controller | changed: [instance]
2025-09-29 18:54:41.778998 | controller |
2025-09-29 18:54:41.779018 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-09-29 18:54:41.779026 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.445)       0:00:19.556 ******
2025-09-29 18:54:41.779035 | controller | skipping: [instance]
2025-09-29 18:54:41.808039 | controller |
2025-09-29 18:54:41.808083 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-09-29 18:54:41.808090 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.028)       0:00:19.585 ******
2025-09-29 18:54:41.808099 | controller | skipping: [instance]
2025-09-29 18:54:41.836999 | controller |
2025-09-29 18:54:41.837017 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-09-29 18:54:41.837024 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.029)       0:00:19.614 ******
2025-09-29 18:54:41.837033 | controller | skipping: [instance]
2025-09-29 18:54:41.875193 | controller |
2025-09-29 18:54:41.875210 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-09-29 18:54:41.875217 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.028)       0:00:19.643 ******
2025-09-29 18:54:41.875233 | controller | ok: [instance]
2025-09-29 18:54:41.902111 | controller |
2025-09-29 18:54:41.902133 | controller | TASK [repo_setup : Create download directory] **********************************
2025-09-29 18:54:41.902141 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.038)       0:00:19.681 ******
2025-09-29 18:54:41.902152 | controller | skipping: [instance]
2025-09-29 18:54:41.902290 | controller |
2025-09-29 18:54:41.902303 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-09-29 18:54:41.902313 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.026)       0:00:19.708 ******
2025-09-29 18:54:41.928632 | controller | skipping: [instance]
2025-09-29 18:54:41.928784 | controller |
2025-09-29 18:54:41.928928 | controller | TASK [Download the RPM] ********************************************************
2025-09-29 18:54:41.929111 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.026)       0:00:19.735 ******
2025-09-29 18:54:41.955105 | controller | skipping: [instance]
2025-09-29 18:54:41.955293 | controller |
2025-09-29 18:54:41.955467 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-09-29 18:54:41.955631 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.026)       0:00:19.761 ******
2025-09-29 18:54:41.982114 | controller | skipping: [instance]
2025-09-29 18:54:41.982314 | controller |
2025-09-29 18:54:41.982492 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-09-29 18:54:41.982660 | controller | Monday 29 September 2025  18:54:41 +0000 (0:00:00.026)       0:00:19.788 ******
2025-09-29 18:54:42.008399 | controller | skipping: [instance]
2025-09-29 18:54:42.008561 | controller |
2025-09-29 18:54:42.008708 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-09-29 18:54:42.008862 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.026)       0:00:19.815 ******
2025-09-29 18:54:42.036489 | controller | skipping: [instance]
2025-09-29 18:54:42.036668 | controller |
2025-09-29 18:54:42.036835 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-09-29 18:54:42.036976 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.028)       0:00:19.843 ******
2025-09-29 18:54:42.063022 | controller | skipping: [instance]
2025-09-29 18:54:42.063211 | controller |
2025-09-29 18:54:42.063358 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-09-29 18:54:42.063498 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.026)       0:00:19.869 ******
2025-09-29 18:54:42.250171 | controller | ok: [instance]
2025-09-29 18:54:42.250221 | controller |
2025-09-29 18:54:42.250431 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-09-29 18:54:42.463833 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.186)       0:00:20.056 ******
2025-09-29 18:54:42.463866 | controller | changed: [instance]
2025-09-29 18:54:42.731088 | controller |
2025-09-29 18:54:42.731117 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-09-29 18:54:42.731125 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.213)       0:00:20.269 ******
2025-09-29 18:54:42.731135 | controller | changed: [instance]
2025-09-29 18:54:42.752665 | controller |
2025-09-29 18:54:42.752690 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-09-29 18:54:42.752698 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.267)       0:00:20.537 ******
2025-09-29 18:54:42.752708 | controller | skipping: [instance]
2025-09-29 18:54:42.776883 | controller |
2025-09-29 18:54:42.776931 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-09-29 18:54:42.776941 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.021)       0:00:20.558 ******
2025-09-29 18:54:42.776956 | controller | skipping: [instance]
2025-09-29 18:54:42.800113 | controller |
2025-09-29 18:54:42.800146 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-09-29 18:54:42.800154 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.023)       0:00:20.582 ******
2025-09-29 18:54:42.800164 | controller | skipping: [instance]
2025-09-29 18:54:42.824162 | controller |
2025-09-29 18:54:42.824199 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-09-29 18:54:42.824217 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.023)       0:00:20.606 ******
2025-09-29 18:54:42.824231 | controller | skipping: [instance]
2025-09-29 18:54:42.847881 | controller |
2025-09-29 18:54:42.847922 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-09-29 18:54:42.847933 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.024)       0:00:20.630 ******
2025-09-29 18:54:42.847946 | controller | skipping: [instance]
2025-09-29 18:54:42.848016 | controller |
2025-09-29 18:54:42.848188 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-09-29 18:54:42.848317 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.023)       0:00:20.654 ******
2025-09-29 18:54:42.871844 | controller | skipping: [instance]
2025-09-29 18:54:42.871976 | controller |
2025-09-29 18:54:42.872181 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-09-29 18:54:42.872314 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.024)       0:00:20.678 ******
2025-09-29 18:54:42.890761 | controller | skipping: [instance]
2025-09-29 18:54:42.890889 | controller |
2025-09-29 18:54:42.891017 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-09-29 18:54:42.891182 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.019)       0:00:20.697 ******
2025-09-29 18:54:42.920992 | controller | skipping: [instance]
2025-09-29 18:54:42.921146 | controller |
2025-09-29 18:54:42.921278 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-09-29 18:54:42.921400 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.030)       0:00:20.727 ******
2025-09-29 18:54:42.940032 | controller | skipping: [instance]
2025-09-29 18:54:42.940224 | controller |
2025-09-29 18:54:42.940386 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-09-29 18:54:42.940523 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.018)       0:00:20.746 ******
2025-09-29 18:54:42.961491 | controller | skipping: [instance]
2025-09-29 18:54:42.961617 | controller |
2025-09-29 18:54:42.961744 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-09-29 18:54:42.961868 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.021)       0:00:20.768 ******
2025-09-29 18:54:42.992132 | controller | skipping: [instance]
2025-09-29 18:54:42.992299 | controller |
2025-09-29 18:54:42.992457 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-09-29 18:54:42.992604 | controller | Monday 29 September 2025  18:54:42 +0000 (0:00:00.030)       0:00:20.798 ******
2025-09-29 18:54:43.019667 | controller | skipping: [instance]
2025-09-29 18:54:43.019786 | controller |
2025-09-29 18:54:43.019917 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-09-29 18:54:43.020071 | controller | Monday 29 September 2025  18:54:43 +0000 (0:00:00.027)       0:00:20.826 ******
2025-09-29 18:54:43.048220 | controller | skipping: [instance]
2025-09-29 18:54:43.048332 | controller |
2025-09-29 18:54:43.048456 | controller | TASK [test_deps : Install additional packages] *********************************
2025-09-29 18:54:43.048574 | controller | Monday 29 September 2025  18:54:43 +0000 (0:00:00.028)       0:00:20.854 ******
2025-09-29 18:54:43.076754 | controller | skipping: [instance]
2025-09-29 18:54:43.076855 | controller |
2025-09-29 18:54:43.076974 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-09-29 18:54:43.077112 | controller | Monday 29 September 2025  18:54:43 +0000 (0:00:00.028)       0:00:20.883 ******
2025-09-29 18:55:21.542568 | controller | ok: [instance]
2025-09-29 18:55:22.787615 | controller |
2025-09-29 18:55:22.787659 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-09-29 18:55:22.787668 | controller | Monday 29 September 2025  18:55:21 +0000 (0:00:38.465)       0:00:59.348 ******
2025-09-29 18:55:22.787681 | controller | ok: [instance]
2025-09-29 18:55:22.820163 | controller |
2025-09-29 18:55:22.820196 | controller | TASK [test_deps : Install extra packages] **************************************
2025-09-29 18:55:22.820204 | controller | Monday 29 September 2025  18:55:22 +0000 (0:00:01.245)       0:01:00.593 ******
2025-09-29 18:55:22.820214 | controller | skipping: [instance]
2025-09-29 18:55:22.820242 | controller |
2025-09-29 18:55:22.820251 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-09-29 18:55:22.820351 | controller | Monday 29 September 2025  18:55:22 +0000 (0:00:00.032)       0:01:00.626 ******
2025-09-29 18:55:23.015385 | controller | ok: [instance]
2025-09-29 18:55:23.195507 | controller |
2025-09-29 18:55:23.195536 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-09-29 18:55:23.195549 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.194)       0:01:00.821 ******
2025-09-29 18:55:23.195560 | controller | changed: [instance]
2025-09-29 18:55:23.386157 | controller |
2025-09-29 18:55:23.386184 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-09-29 18:55:23.386192 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.180)       0:01:01.001 ******
2025-09-29 18:55:23.386202 | controller | ok: [instance]
2025-09-29 18:55:23.413652 | controller |
2025-09-29 18:55:23.413675 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-09-29 18:55:23.413683 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.190)       0:01:01.192 ******
2025-09-29 18:55:23.413692 | controller | skipping: [instance]
2025-09-29 18:55:23.430584 | controller |
2025-09-29 18:55:23.430603 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-09-29 18:55:23.430610 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.027)       0:01:01.220 ******
2025-09-29 18:55:23.430619 | controller | skipping: [instance]
2025-09-29 18:55:23.451681 | controller |
2025-09-29 18:55:23.451699 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-09-29 18:55:23.451706 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.016)       0:01:01.237 ******
2025-09-29 18:55:23.451715 | controller | ok: [instance]
2025-09-29 18:55:23.479138 | controller |
2025-09-29 18:55:23.479176 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-09-29 18:55:23.479184 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.021)       0:01:01.258 ******
2025-09-29 18:55:23.479194 | controller | skipping: [instance]
2025-09-29 18:55:23.479211 | controller |
2025-09-29 18:55:23.479219 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-09-29 18:55:23.479301 | controller | Monday 29 September 2025  18:55:23 +0000 (0:00:00.027)       0:01:01.285 ******
2025-09-29 18:56:40.398827 | controller | changed: [instance]
2025-09-29 18:56:40.612746 | controller |
2025-09-29 18:56:40.612777 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-09-29 18:56:40.612785 | controller | Monday 29 September 2025  18:56:40 +0000 (0:01:16.919)       0:02:18.204 ******
2025-09-29 18:56:40.612795 | controller | changed: [instance]
2025-09-29 18:56:41.008160 | controller |
2025-09-29 18:56:41.008195 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-09-29 18:56:41.008203 | controller | Monday 29 September 2025  18:56:40 +0000 (0:00:00.213)       0:02:18.418 ******
2025-09-29 18:56:41.008214 | controller | changed: [instance]
2025-09-29 18:56:41.590727 | controller |
2025-09-29 18:56:41.590758 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-09-29 18:56:41.590766 | controller | Monday 29 September 2025  18:56:41 +0000 (0:00:00.395)       0:02:18.814 ******
2025-09-29 18:56:41.590776 | controller | changed: [instance]
2025-09-29 18:56:41.591197 | controller |
2025-09-29 18:56:41.784699 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-09-29 18:56:41.784730 | controller | Monday 29 September 2025  18:56:41 +0000 (0:00:00.582)       0:02:19.397 ******
2025-09-29 18:56:41.784742 | controller | ok: [instance]
2025-09-29 18:56:41.784875 | controller |
2025-09-29 18:56:41.785027 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-09-29 18:56:41.785075 | controller | Monday 29 September 2025  18:56:41 +0000 (0:00:00.193)       0:02:19.591 ******
2025-09-29 18:56:42.475071 | controller | ok: [instance]
2025-09-29 18:56:42.475433 | controller |
2025-09-29 18:56:43.298675 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-09-29 18:56:43.298706 | controller | Monday 29 September 2025  18:56:42 +0000 (0:00:00.690)       0:02:20.281 ******
2025-09-29 18:56:43.298724 | controller | changed: [instance]
2025-09-29 18:56:43.298907 | controller |
2025-09-29 18:56:43.375103 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-09-29 18:56:43.375132 | controller | Monday 29 September 2025  18:56:43 +0000 (0:00:00.823)       0:02:21.104 ******
2025-09-29 18:56:43.375143 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-09-29 18:56:43.375556 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-09-29 18:56:43.375654 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-09-29 18:56:43.375664 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-09-29 18:56:43.375670 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-09-29 18:56:43.375678 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-09-29 18:56:43.375774 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-09-29 18:56:43.376229 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-09-29 18:56:43.714308 | controller |
2025-09-29 18:56:43.714338 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-09-29 18:56:43.714346 | controller | Monday 29 September 2025  18:56:43 +0000 (0:00:00.076)       0:02:21.181 ******
2025-09-29 18:56:43.714356 | controller | changed: [instance]
2025-09-29 18:56:44.052167 | controller |
2025-09-29 18:56:44.052200 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-09-29 18:56:44.052208 | controller | Monday 29 September 2025  18:56:43 +0000 (0:00:00.338)       0:02:21.520 ******
2025-09-29 18:56:44.052224 | controller | changed: [instance]
2025-09-29 18:56:44.384218 | controller |
2025-09-29 18:56:44.384248 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-09-29 18:56:44.384256 | controller | Monday 29 September 2025  18:56:44 +0000 (0:00:00.337)       0:02:21.858 ******
2025-09-29 18:56:44.384266 | controller | changed: [instance]
2025-09-29 18:56:44.717762 | controller |
2025-09-29 18:56:44.717794 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-09-29 18:56:44.717801 | controller | Monday 29 September 2025  18:56:44 +0000 (0:00:00.332)       0:02:22.190 ******
2025-09-29 18:56:44.717812 | controller | changed: [instance]
2025-09-29 18:56:45.061860 | controller |
2025-09-29 18:56:45.061890 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-09-29 18:56:45.061899 | controller | Monday 29 September 2025  18:56:44 +0000 (0:00:00.333)       0:02:22.523 ******
2025-09-29 18:56:45.061909 | controller | changed: [instance]
2025-09-29 18:56:45.389238 | controller |
2025-09-29 18:56:45.389269 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-09-29 18:56:45.389277 | controller | Monday 29 September 2025  18:56:45 +0000 (0:00:00.344)       0:02:22.868 ******
2025-09-29 18:56:45.389287 | controller | changed: [instance]
2025-09-29 18:56:45.734146 | controller |
2025-09-29 18:56:45.734178 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-09-29 18:56:45.734186 | controller | Monday 29 September 2025  18:56:45 +0000 (0:00:00.327)       0:02:23.195 ******
2025-09-29 18:56:45.734196 | controller | changed: [instance]
2025-09-29 18:56:46.061598 | controller |
2025-09-29 18:56:46.061627 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-09-29 18:56:46.061635 | controller | Monday 29 September 2025  18:56:45 +0000 (0:00:00.344)       0:02:23.540 ******
2025-09-29 18:56:46.061644 | controller | changed: [instance]
2025-09-29 18:56:46.398922 | controller |
2025-09-29 18:56:46.398972 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-09-29 18:56:46.398981 | controller | Monday 29 September 2025  18:56:46 +0000 (0:00:00.327)       0:02:23.867 ******
2025-09-29 18:56:46.398992 | controller | changed: [instance]
2025-09-29 18:56:46.736150 | controller |
2025-09-29 18:56:46.736180 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-09-29 18:56:46.736188 | controller | Monday 29 September 2025  18:56:46 +0000 (0:00:00.337)       0:02:24.205 ******
2025-09-29 18:56:46.736199 | controller | changed: [instance]
2025-09-29 18:56:46.736308 | controller |
2025-09-29 18:56:46.736319 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-09-29 18:56:46.736327 | controller | Monday 29 September 2025  18:56:46 +0000 (0:00:00.337)       0:02:24.542 ******
2025-09-29 18:56:47.074506 | controller | changed: [instance]
2025-09-29 18:56:47.407129 | controller |
2025-09-29 18:56:47.407159 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-09-29 18:56:47.407167 | controller | Monday 29 September 2025  18:56:47 +0000 (0:00:00.338)       0:02:24.880 ******
2025-09-29 18:56:47.407177 | controller | changed: [instance]
2025-09-29 18:56:47.749345 | controller |
2025-09-29 18:56:47.749376 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-09-29 18:56:47.749384 | controller | Monday 29 September 2025  18:56:47 +0000 (0:00:00.332)       0:02:25.213 ******
2025-09-29 18:56:47.749394 | controller | changed: [instance]
2025-09-29 18:56:48.129296 | controller |
2025-09-29 18:56:48.129325 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-09-29 18:56:48.129333 | controller | Monday 29 September 2025  18:56:47 +0000 (0:00:00.342)       0:02:25.555 ******
2025-09-29 18:56:48.129343 | controller | changed: [instance]
2025-09-29 18:56:48.467909 | controller |
2025-09-29 18:56:48.467938 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-09-29 18:56:48.467946 | controller | Monday 29 September 2025  18:56:48 +0000 (0:00:00.379)       0:02:25.935 ******
2025-09-29 18:56:48.467970 | controller | changed: [instance]
2025-09-29 18:56:48.799658 | controller |
2025-09-29 18:56:48.799688 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-09-29 18:56:48.799696 | controller | Monday 29 September 2025  18:56:48 +0000 (0:00:00.338)       0:02:26.274 ******
2025-09-29 18:56:48.799706 | controller | changed: [instance]
2025-09-29 18:56:50.171324 | controller |
2025-09-29 18:56:50.171354 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-09-29 18:56:50.171362 | controller | Monday 29 September 2025  18:56:48 +0000 (0:00:00.331)       0:02:26.605 ******
2025-09-29 18:56:50.171372 | controller | changed: [instance]
2025-09-29 18:56:50.505145 | controller |
2025-09-29 18:56:50.505183 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-09-29 18:56:50.505197 | controller | Monday 29 September 2025  18:56:50 +0000 (0:00:01.371)       0:02:27.977 ******
2025-09-29 18:56:50.505207 | controller | changed: [instance]
2025-09-29 18:56:50.836125 | controller |
2025-09-29 18:56:50.836155 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-09-29 18:56:50.836163 | controller | Monday 29 September 2025  18:56:50 +0000 (0:00:00.333)       0:02:28.311 ******
2025-09-29 18:56:50.836173 | controller | changed: [instance]
2025-09-29 18:56:51.186001 | controller |
2025-09-29 18:56:51.186030 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-09-29 18:56:51.186038 | controller | Monday 29 September 2025  18:56:50 +0000 (0:00:00.331)       0:02:28.642 ******
2025-09-29 18:56:51.186048 | controller | changed: [instance]
2025-09-29 18:56:51.524388 | controller |
2025-09-29 18:56:51.524423 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-09-29 18:56:51.524433 | controller | Monday 29 September 2025  18:56:51 +0000 (0:00:00.349)       0:02:28.992 ******
2025-09-29 18:56:51.524445 | controller | changed: [instance]
2025-09-29 18:56:51.854102 | controller |
2025-09-29 18:56:51.854135 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-09-29 18:56:51.854143 | controller | Monday 29 September 2025  18:56:51 +0000 (0:00:00.338)       0:02:29.330 ******
2025-09-29 18:56:51.854161 | controller | changed: [instance]
2025-09-29 18:56:52.198279 | controller |
2025-09-29 18:56:52.198317 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-09-29 18:56:52.198325 | controller | Monday 29 September 2025  18:56:51 +0000 (0:00:00.329)       0:02:29.660 ******
2025-09-29 18:56:52.198338 | controller | changed: [instance]
2025-09-29 18:56:52.545038 | controller |
2025-09-29 18:56:52.545104 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-09-29 18:56:52.545114 | controller | Monday 29 September 2025  18:56:52 +0000 (0:00:00.344)       0:02:30.004 ******
2025-09-29 18:56:52.545124 | controller | changed: [instance]
2025-09-29 18:56:52.564764 | controller |
2025-09-29 18:56:52.564786 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-09-29 18:56:52.564794 | controller | Monday 29 September 2025  18:56:52 +0000 (0:00:00.346)       0:02:30.351 ******
2025-09-29 18:56:52.564803 | controller | skipping: [instance]
2025-09-29 18:56:52.846232 | controller |
2025-09-29 18:56:52.846262 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-09-29 18:56:52.846270 | controller | Monday 29 September 2025  18:56:52 +0000 (0:00:00.019)       0:02:30.370 ******
2025-09-29 18:56:52.846280 | controller | ok: [instance]
2025-09-29 18:56:53.260596 | controller |
2025-09-29 18:56:53.260627 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-09-29 18:56:53.260636 | controller | Monday 29 September 2025  18:56:52 +0000 (0:00:00.281)       0:02:30.652 ******
2025-09-29 18:56:53.260645 | controller | changed: [instance]
2025-09-29 18:56:53.576887 | controller |
2025-09-29 18:56:53.576918 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-09-29 18:56:53.576926 | controller | Monday 29 September 2025  18:56:53 +0000 (0:00:00.414)       0:02:31.066 ******
2025-09-29 18:56:53.576935 | controller | changed: [instance]
2025-09-29 18:56:53.858172 | controller |
2025-09-29 18:56:53.858205 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-09-29 18:56:53.858213 | controller | Monday 29 September 2025  18:56:53 +0000 (0:00:00.316)       0:02:31.382 ******
2025-09-29 18:56:53.858223 | controller | [WARNING]: Reset is not implemented for this connection
2025-09-29 18:56:53.883252 | controller | changed: [instance]
2025-09-29 18:56:53.946239 | controller |
2025-09-29 18:56:53.946286 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-09-29 18:56:53.946295 | controller | Monday 29 September 2025  18:56:53 +0000 (0:00:00.276)       0:02:31.659 ******
2025-09-29 18:56:53.946301 | controller |
2025-09-29 18:56:53.946307 | controller | PLAY RECAP *********************************************************************
2025-09-29 18:56:53.946313 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-09-29 18:56:53.946318 | controller |
2025-09-29 18:56:53.946324 | controller | Monday 29 September 2025  18:56:53 +0000 (0:00:00.026)       0:02:31.686 ******
2025-09-29 18:56:53.946329 | controller | ===============================================================================
2025-09-29 18:56:53.946334 | controller | libvirt_manager : Install packages required for using KVM -------------- 76.92s
2025-09-29 18:56:53.946340 | controller | test_deps : Install selinux python libs -------------------------------- 38.47s
2025-09-29 18:56:53.946345 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.95s
2025-09-29 18:56:53.946361 | controller | Install some debug utils ------------------------------------------------ 4.03s
2025-09-29 18:56:53.946366 | controller | libvirt_manager : Ensure read-only socket is enabled for secret. -------- 1.37s
2025-09-29 18:56:53.946372 | controller | test_deps : Install python yaml libs ------------------------------------ 1.25s
2025-09-29 18:56:53.946377 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.16s
2025-09-29 18:56:53.946382 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.83s
2025-09-29 18:56:53.946387 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.82s
2025-09-29 18:56:53.946393 | controller | Gathering Facts --------------------------------------------------------- 0.81s
2025-09-29 18:56:53.946398 | controller | repo_setup : Install repo-setup package --------------------------------- 0.72s
2025-09-29 18:56:53.946410 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.71s
2025-09-29 18:56:53.946416 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.69s
2025-09-29 18:56:53.946421 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.66s
2025-09-29 18:56:53.946426 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.59s
2025-09-29 18:56:53.946432 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.58s
2025-09-29 18:56:53.946437 | controller | repo_setup : Ensure directories are present ----------------------------- 0.57s
2025-09-29 18:56:53.946442 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.45s
2025-09-29 18:56:53.946448 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.41s
2025-09-29 18:56:53.946453 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.40s
2025-09-29 18:56:53.946466 | controller | INFO     Running default > converge
2025-09-29 18:56:54.393493 | controller |
2025-09-29 18:56:55.198759 | controller | PLAY [Converge] ****************************************************************
2025-09-29 18:56:55.198791 | controller |
2025-09-29 18:56:55.198799 | controller | TASK [Gathering Facts] *********************************************************
2025-09-29 18:56:55.198805 | controller | Monday 29 September 2025  18:56:54 +0000 (0:00:00.014)       0:00:00.014 ******
2025-09-29 18:56:55.198814 | controller | ok: [instance]
2025-09-29 18:56:55.567615 | controller |
2025-09-29 18:56:55.567645 | controller | TASK [Crate SSH keypair] *******************************************************
2025-09-29 18:56:55.567653 | controller | Monday 29 September 2025  18:56:55 +0000 (0:00:00.805)       0:00:00.820 ******
2025-09-29 18:56:55.567663 | controller | changed: [instance]
2025-09-29 18:56:56.067120 | controller |
2025-09-29 18:56:56.067153 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-09-29 18:56:56.067162 | controller | Monday 29 September 2025  18:56:55 +0000 (0:00:00.368)       0:00:01.189 ******
2025-09-29 18:56:56.067172 | controller | changed: [instance]
2025-09-29 18:56:57.028226 | controller |
2025-09-29 18:56:57.028260 | controller | TASK [Restart firewalld.service] ***********************************************
2025-09-29 18:56:57.028269 | controller | Monday 29 September 2025  18:56:56 +0000 (0:00:00.499)       0:00:01.688 ******
2025-09-29 18:56:57.028279 | controller | changed: [instance]
2025-09-29 18:56:57.028299 | controller |
2025-09-29 18:56:57.028305 | controller | TASK [Discover latest image] ***************************************************
2025-09-29 18:56:57.028312 | controller | Monday 29 September 2025  18:56:57 +0000 (0:00:00.961)       0:00:02.650 ******
2025-09-29 18:56:57.068894 | controller |
2025-09-29 18:56:58.650376 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-09-29 18:56:58.650407 | controller | Monday 29 September 2025  18:56:57 +0000 (0:00:00.040)       0:00:02.690 ******
2025-09-29 18:56:58.650418 | controller | changed: [instance]
2025-09-29 18:56:58.676468 | controller |
2025-09-29 18:56:58.676492 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-09-29 18:56:58.676506 | controller | Monday 29 September 2025  18:56:58 +0000 (0:00:01.581)       0:00:04.272 ******
2025-09-29 18:56:58.676516 | controller | ok: [instance]
2025-09-29 18:57:21.770314 | controller |
2025-09-29 18:57:21.770347 | controller | TASK [Download latest image] ***************************************************
2025-09-29 18:57:21.770355 | controller | Monday 29 September 2025  18:56:58 +0000 (0:00:00.026)       0:00:04.298 ******
2025-09-29 18:57:21.770365 | controller | changed: [instance]
2025-09-29 18:57:21.806146 | controller |
2025-09-29 18:57:21.806186 | controller | TASK [Build nat64 appliance image] *********************************************
2025-09-29 18:57:21.806196 | controller | Monday 29 September 2025  18:57:21 +0000 (0:00:23.093)       0:00:27.392 ******
2025-09-29 18:57:21.806209 | controller |
2025-09-29 18:57:22.298521 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-09-29 18:57:22.298553 | controller | Monday 29 September 2025  18:57:21 +0000 (0:00:00.035)       0:00:27.428 ******
2025-09-29 18:57:22.298573 | controller | ok: [instance] => (item=artifacts)
2025-09-29 18:57:22.502794 | controller | ok: [instance] => (item=logs)
2025-09-29 18:57:22.502827 | controller |
2025-09-29 18:57:22.502834 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-09-29 18:57:22.502841 | controller | Monday 29 September 2025  18:57:22 +0000 (0:00:00.492)       0:00:27.920 ******
2025-09-29 18:57:22.502851 | controller | changed: [instance]
2025-09-29 18:57:26.907522 | controller |
2025-09-29 18:57:26.907556 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-09-29 18:57:26.907564 | controller | Monday 29 September 2025  18:57:22 +0000 (0:00:00.204)       0:00:28.124 ******
2025-09-29 18:57:26.907574 | controller | ok: [instance]
2025-09-29 18:57:35.084604 | controller |
2025-09-29 18:57:35.084635 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-09-29 18:57:35.084644 | controller | Monday 29 September 2025  18:57:26 +0000 (0:00:04.404)       0:00:32.529 ******
2025-09-29 18:57:35.084654 | controller | changed: [instance]
2025-09-29 18:57:45.213224 | controller |
2025-09-29 18:57:45.213259 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-09-29 18:57:45.213267 | controller | Monday 29 September 2025  18:57:35 +0000 (0:00:08.177)       0:00:40.706 ******
2025-09-29 18:57:45.213278 | controller | changed: [instance] => (item=elements/)
2025-09-29 18:57:46.359159 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-09-29 18:57:46.359192 | controller |
2025-09-29 18:57:46.359199 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-09-29 18:57:46.359205 | controller | Monday 29 September 2025  18:57:45 +0000 (0:00:10.128)       0:00:50.834 ******
2025-09-29 18:57:46.359216 | controller | changed: [instance]
2025-09-29 18:57:46.359440 | controller |
2025-09-29 18:57:46.359454 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-09-29 19:02:36.620034 | controller | Monday 29 September 2025  18:57:46 +0000 (0:00:01.146)       0:00:51.981 ******
2025-09-29 19:02:36.620373 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-09-29 19:02:36.829787 | controller | changed: [instance]
2025-09-29 19:02:36.829817 | controller |
2025-09-29 19:02:36.829825 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-09-29 19:02:36.829832 | controller | Monday 29 September 2025  19:02:36 +0000 (0:04:50.260)       0:05:42.241 ******
2025-09-29 19:02:36.829842 | controller | changed: [instance]
2025-09-29 19:02:44.250736 | controller |
2025-09-29 19:02:44.250774 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-09-29 19:02:44.250782 | controller | Monday 29 September 2025  19:02:36 +0000 (0:00:00.209)       0:05:42.451 ******
2025-09-29 19:02:44.250793 | controller | changed: [instance]
2025-09-29 19:02:44.296269 | controller |
2025-09-29 19:02:44.296314 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-09-29 19:02:44.296325 | controller | Monday 29 September 2025  19:02:44 +0000 (0:00:07.420)       0:05:49.872 ******
2025-09-29 19:02:44.296338 | controller |
2025-09-29 19:02:44.350513 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-09-29 19:02:44.350547 | controller | Monday 29 September 2025  19:02:44 +0000 (0:00:00.045)       0:05:49.918 ******
2025-09-29 19:02:44.350559 | controller | ok: [instance]
2025-09-29 19:02:45.178648 | controller |
2025-09-29 19:02:45.178681 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-09-29 19:02:45.178690 | controller | Monday 29 September 2025  19:02:44 +0000 (0:00:00.054)       0:05:49.972 ******
2025-09-29 19:02:45.178700 | controller | changed: [instance]
2025-09-29 19:02:45.537991 | controller |
2025-09-29 19:02:45.538026 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-09-29 19:02:45.538035 | controller | Monday 29 September 2025  19:02:45 +0000 (0:00:00.827)       0:05:50.800 ******
2025-09-29 19:02:45.538078 | controller | ok: [instance]
2025-09-29 19:02:45.770516 | controller |
2025-09-29 19:02:45.770548 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-09-29 19:02:45.770556 | controller | Monday 29 September 2025  19:02:45 +0000 (0:00:00.359)       0:05:51.159 ******
2025-09-29 19:02:45.770573 | controller | ok: [instance]
2025-09-29 19:02:45.993609 | controller |
2025-09-29 19:02:45.993641 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-09-29 19:02:45.993650 | controller | Monday 29 September 2025  19:02:45 +0000 (0:00:00.232)       0:05:51.392 ******
2025-09-29 19:02:45.993660 | controller | changed: [instance]
2025-09-29 19:02:46.225000 | controller |
2025-09-29 19:02:46.225038 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-09-29 19:02:46.225047 | controller | Monday 29 September 2025  19:02:45 +0000 (0:00:00.222)       0:05:51.615 ******
2025-09-29 19:02:46.225086 | controller | changed: [instance]
2025-09-29 19:02:46.470039 | controller |
2025-09-29 19:02:46.470087 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-09-29 19:02:46.470095 | controller | Monday 29 September 2025  19:02:46 +0000 (0:00:00.231)       0:05:51.846 ******
2025-09-29 19:02:46.470106 | controller | ok: [instance]
2025-09-29 19:02:46.692133 | controller |
2025-09-29 19:02:46.692176 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-09-29 19:02:46.692184 | controller | Monday 29 September 2025  19:02:46 +0000 (0:00:00.244)       0:05:52.091 ******
2025-09-29 19:02:46.692195 | controller | ok: [instance]
2025-09-29 19:02:46.916667 | controller |
2025-09-29 19:02:46.916698 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-09-29 19:02:46.916706 | controller | Monday 29 September 2025  19:02:46 +0000 (0:00:00.222)       0:05:52.314 ******
2025-09-29 19:02:46.916717 | controller | changed: [instance]
2025-09-29 19:02:47.694416 | controller |
2025-09-29 19:02:47.694447 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-09-29 19:02:47.694455 | controller | Monday 29 September 2025  19:02:46 +0000 (0:00:00.224)       0:05:52.538 ******
2025-09-29 19:02:47.694465 | controller | changed: [instance] => (item=br-64v6)
2025-09-29 19:02:48.587668 | controller | changed: [instance] => (item=br-64v4)
2025-09-29 19:02:48.587700 | controller |
2025-09-29 19:02:48.587708 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-09-29 19:02:48.587715 | controller | Monday 29 September 2025  19:02:47 +0000 (0:00:00.777)       0:05:53.316 ******
2025-09-29 19:02:48.587725 | controller | changed: [instance]
2025-09-29 19:02:48.621536 | controller |
2025-09-29 19:02:48.621565 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-09-29 19:02:48.621573 | controller | Monday 29 September 2025  19:02:48 +0000 (0:00:00.892)       0:05:54.209 ******
2025-09-29 19:02:48.621583 | controller | ok: [instance]
2025-09-29 19:02:48.661225 | controller |
2025-09-29 19:02:48.661256 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-09-29 19:02:48.661265 | controller | Monday 29 September 2025  19:02:48 +0000 (0:00:00.034)       0:05:54.243 ******
2025-09-29 19:02:48.661275 | controller |
2025-09-29 19:02:49.051555 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-09-29 19:02:49.051585 | controller | Monday 29 September 2025  19:02:48 +0000 (0:00:00.039)       0:05:54.283 ******
2025-09-29 19:02:49.051598 | controller | ok: [instance] => (item=artifacts)
2025-09-29 19:02:50.388341 | controller | ok: [instance] => (item=logs)
2025-09-29 19:02:50.388384 | controller |
2025-09-29 19:02:50.388393 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-09-29 19:02:50.388400 | controller | Monday 29 September 2025  19:02:49 +0000 (0:00:00.390)       0:05:54.673 ******
2025-09-29 19:02:50.388412 | controller | ok: [instance]
2025-09-29 19:02:50.597037 | controller |
2025-09-29 19:02:50.597084 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-09-29 19:02:50.597093 | controller | Monday 29 September 2025  19:02:50 +0000 (0:00:01.336)       0:05:56.009 ******
2025-09-29 19:02:50.597104 | controller | changed: [instance]
2025-09-29 19:02:50.958655 | controller |
2025-09-29 19:02:50.958686 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-09-29 19:02:50.958694 | controller | Monday 29 September 2025  19:02:50 +0000 (0:00:00.209)       0:05:56.218 ******
2025-09-29 19:02:50.958704 | controller | changed: [instance]
2025-09-29 19:02:51.349991 | controller |
2025-09-29 19:02:51.350022 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-09-29 19:02:51.350030 | controller | Monday 29 September 2025  19:02:50 +0000 (0:00:00.361)       0:05:56.580 ******
2025-09-29 19:02:51.350040 | controller | changed: [instance]
2025-09-29 19:02:51.735742 | controller |
2025-09-29 19:02:51.735776 | controller | TASK [config_drive : Generate network-data] ************************************
2025-09-29 19:02:51.735791 | controller | Monday 29 September 2025  19:02:51 +0000 (0:00:00.391)       0:05:56.971 ******
2025-09-29 19:02:51.735802 | controller | changed: [instance]
2025-09-29 19:02:51.928839 | controller |
2025-09-29 19:02:51.928871 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-09-29 19:02:51.928879 | controller | Monday 29 September 2025  19:02:51 +0000 (0:00:00.385)       0:05:57.357 ******
2025-09-29 19:02:51.928889 | controller | ok: [instance]
2025-09-29 19:02:51.946148 | controller |
2025-09-29 19:02:51.946174 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-09-29 19:02:51.946184 | controller | Monday 29 September 2025  19:02:51 +0000 (0:00:00.193)       0:05:57.550 ******
2025-09-29 19:02:51.946196 | controller | skipping: [instance]
2025-09-29 19:02:52.180645 | controller |
2025-09-29 19:02:52.180680 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-09-29 19:02:52.180689 | controller | Monday 29 September 2025  19:02:51 +0000 (0:00:00.017)       0:05:57.568 ******
2025-09-29 19:02:52.180699 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-09-29 19:02:53.325851 | controller | changed: [instance]
2025-09-29 19:02:53.325885 | controller |
2025-09-29 19:02:53.325893 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-09-29 19:02:53.325899 | controller | Monday 29 September 2025  19:02:52 +0000 (0:00:00.234)       0:05:57.802 ******
2025-09-29 19:02:53.325909 | controller | changed: [instance]
2025-09-29 19:02:54.211933 | controller |
2025-09-29 19:02:54.211966 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-09-29 19:02:54.211974 | controller | Monday 29 September 2025  19:02:53 +0000 (0:00:01.145)       0:05:58.947 ******
2025-09-29 19:02:54.211984 | controller | changed: [instance]
2025-09-29 19:02:54.235470 | controller |
2025-09-29 19:02:54.235497 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-09-29 19:02:54.235505 | controller | Monday 29 September 2025  19:02:54 +0000 (0:00:00.886)       0:05:59.833 ******
2025-09-29 19:02:54.235515 | controller | ok: [instance]
2025-09-29 19:02:54.278050 | controller |
2025-09-29 19:02:54.278116 | controller | TASK [Set MAC address facts] ***************************************************
2025-09-29 19:02:54.278125 | controller | Monday 29 September 2025  19:02:54 +0000 (0:00:00.023)       0:05:59.857 ******
2025-09-29 19:02:54.278140 | controller | ok: [instance]
2025-09-29 19:02:54.519884 | controller |
2025-09-29 19:02:54.519928 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-09-29 19:02:54.519941 | controller | Monday 29 September 2025  19:02:54 +0000 (0:00:00.042)       0:05:59.899 ******
2025-09-29 19:02:54.519958 | controller | changed: [instance]
2025-09-29 19:02:54.791378 | controller |
2025-09-29 19:02:54.791410 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-09-29 19:02:54.791419 | controller | Monday 29 September 2025  19:02:54 +0000 (0:00:00.241)       0:06:00.141 ******
2025-09-29 19:02:54.791429 | controller | ok: [instance]
2025-09-29 19:02:55.030966 | controller |
2025-09-29 19:02:55.030998 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-09-29 19:02:55.031006 | controller | Monday 29 September 2025  19:02:54 +0000 (0:00:00.271)       0:06:00.413 ******
2025-09-29 19:02:55.031016 | controller | ok: [instance]
2025-09-29 19:02:55.275760 | controller |
2025-09-29 19:02:55.275795 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-09-29 19:02:55.275803 | controller | Monday 29 September 2025  19:02:55 +0000 (0:00:00.239)       0:06:00.652 ******
2025-09-29 19:02:55.275814 | controller | changed: [instance]
2025-09-29 19:02:55.619860 | controller |
2025-09-29 19:02:55.619891 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-09-29 19:02:55.619906 | controller | Monday 29 September 2025  19:02:55 +0000 (0:00:00.244)       0:06:00.897 ******
2025-09-29 19:02:55.619916 | controller | changed: [instance]
2025-09-29 19:02:56.462353 | controller |
2025-09-29 19:02:56.462389 | controller | TASK [Restart firewalld.service] ***********************************************
2025-09-29 19:02:56.462398 | controller | Monday 29 September 2025  19:02:55 +0000 (0:00:00.344)       0:06:01.241 ******
2025-09-29 19:02:56.462408 | controller | changed: [instance]
2025-09-29 19:02:56.498790 | controller |
2025-09-29 19:02:56.498823 | controller | TASK [Generate test node UUID] *************************************************
2025-09-29 19:02:56.498831 | controller | Monday 29 September 2025  19:02:56 +0000 (0:00:00.842)       0:06:02.084 ******
2025-09-29 19:02:56.498841 | controller | ok: [instance]
2025-09-29 19:03:04.741877 | controller |
2025-09-29 19:03:04.741910 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-09-29 19:03:04.741919 | controller | Monday 29 September 2025  19:02:56 +0000 (0:00:00.033)       0:06:02.117 ******
2025-09-29 19:03:04.741945 | controller | changed: [instance]
2025-09-29 19:03:04.793703 | controller |
2025-09-29 19:03:04.793759 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-09-29 19:03:04.793768 | controller | Monday 29 September 2025  19:03:04 +0000 (0:00:08.245)       0:06:10.362 ******
2025-09-29 19:03:04.793782 | controller |
2025-09-29 19:03:05.300123 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-09-29 19:03:05.300161 | controller | Monday 29 September 2025  19:03:04 +0000 (0:00:00.051)       0:06:10.414 ******
2025-09-29 19:03:05.300175 | controller | ok: [instance] => (item=artifacts)
2025-09-29 19:03:06.581164 | controller | ok: [instance] => (item=logs)
2025-09-29 19:03:06.581207 | controller |
2025-09-29 19:03:06.581216 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-09-29 19:03:06.581223 | controller | Monday 29 September 2025  19:03:05 +0000 (0:00:00.506)       0:06:10.921 ******
2025-09-29 19:03:06.581236 | controller | ok: [instance]
2025-09-29 19:03:06.804342 | controller |
2025-09-29 19:03:06.804459 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-09-29 19:03:06.804470 | controller | Monday 29 September 2025  19:03:06 +0000 (0:00:01.278)       0:06:12.199 ******
2025-09-29 19:03:06.804483 | controller | changed: [instance]
2025-09-29 19:03:06.804546 | controller |
2025-09-29 19:03:06.804804 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-09-29 19:03:06.805074 | controller | Monday 29 September 2025  19:03:06 +0000 (0:00:00.225)       0:06:12.425 ******
2025-09-29 19:03:07.170580 | controller | changed: [instance]
2025-09-29 19:03:07.170638 | controller |
2025-09-29 19:03:07.170767 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-09-29 19:03:07.170874 | controller | Monday 29 September 2025  19:03:07 +0000 (0:00:00.367)       0:06:12.792 ******
2025-09-29 19:03:07.531507 | controller | changed: [instance]
2025-09-29 19:03:07.532186 | controller |
2025-09-29 19:03:07.894521 | controller | TASK [config_drive : Generate network-data] ************************************
2025-09-29 19:03:07.894560 | controller | Monday 29 September 2025  19:03:07 +0000 (0:00:00.361)       0:06:13.153 ******
2025-09-29 19:03:07.894574 | controller | changed: [instance]
2025-09-29 19:03:07.894807 | controller |
2025-09-29 19:03:08.082347 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-09-29 19:03:08.082392 | controller | Monday 29 September 2025  19:03:07 +0000 (0:00:00.362)       0:06:13.516 ******
2025-09-29 19:03:08.082409 | controller | ok: [instance]
2025-09-29 19:03:08.103539 | controller |
2025-09-29 19:03:08.103578 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-09-29 19:03:08.103586 | controller | Monday 29 September 2025  19:03:08 +0000 (0:00:00.187)       0:06:13.704 ******
2025-09-29 19:03:08.103599 | controller | skipping: [instance]
2025-09-29 19:03:08.323547 | controller |
2025-09-29 19:03:08.323592 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-09-29 19:03:08.323601 | controller | Monday 29 September 2025  19:03:08 +0000 (0:00:00.018)       0:06:13.723 ******
2025-09-29 19:03:08.323614 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-09-29 19:03:08.598277 | controller | changed: [instance]
2025-09-29 19:03:08.598366 | controller |
2025-09-29 19:03:08.598375 | controller | TASK [Define test-node VM] *****************************************************
2025-09-29 19:03:08.598382 | controller | Monday 29 September 2025  19:03:08 +0000 (0:00:00.222)       0:06:13.945 ******
2025-09-29 19:03:08.598392 | controller | changed: [instance]
2025-09-29 19:03:09.400916 | controller |
2025-09-29 19:03:09.401025 | controller | TASK [Start test-node VM] ******************************************************
2025-09-29 19:03:09.401036 | controller | Monday 29 September 2025  19:03:08 +0000 (0:00:00.274)       0:06:14.220 ******
2025-09-29 19:03:09.401047 | controller | changed: [instance]
2025-09-29 19:03:36.067147 | controller |
2025-09-29 19:03:36.067196 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-09-29 19:03:36.067205 | controller | Monday 29 September 2025  19:03:09 +0000 (0:00:00.802)       0:06:15.022 ******
2025-09-29 19:03:36.067216 | controller | ok: [instance]
2025-09-29 19:03:36.087506 | controller |
2025-09-29 19:03:36.087541 | controller | TASK [Add test node to inventory] **********************************************
2025-09-29 19:03:36.087549 | controller | Monday 29 September 2025  19:03:36 +0000 (0:00:26.666)       0:06:41.688 ******
2025-09-29 19:03:36.087559 | controller | changed: [instance]
2025-09-29 19:03:36.109863 | controller |
2025-09-29 19:03:36.109894 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-09-29 19:03:36.109902 | controller | Monday 29 September 2025  19:03:36 +0000 (0:00:00.020)       0:06:41.709 ******
2025-09-29 19:03:36.109912 | controller | changed: [instance]
2025-09-29 19:03:56.144138 | controller |
2025-09-29 19:03:56.144185 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-09-29 19:03:56.144201 | controller | Monday 29 September 2025  19:03:36 +0000 (0:00:00.022)       0:06:41.731 ******
2025-09-29 19:03:56.144213 | controller | Pausing for 20 seconds
2025-09-29 19:04:02.723882 | controller | ok: [instance]
2025-09-29 19:04:02.723920 | controller |
2025-09-29 19:04:02.723928 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-09-29 19:04:02.723935 | controller | Monday 29 September 2025  19:03:56 +0000 (0:00:20.033)       0:07:01.765 ******
2025-09-29 19:04:02.723946 | controller | changed: [instance]
2025-09-29 19:04:03.796841 | controller |
2025-09-29 19:04:03.796874 | controller | TASK [Grab some info from the test node] ***************************************
2025-09-29 19:04:03.796883 | controller | Monday 29 September 2025  19:04:02 +0000 (0:00:06.580)       0:07:08.345 ******
2025-09-29 19:04:03.796894 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-09-29 19:04:03.796919 | controller |
2025-09-29 19:04:03.797111 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-09-29 19:04:04.861720 | controller | Monday 29 September 2025  19:04:03 +0000 (0:00:01.073)       0:07:09.418 ******
2025-09-29 19:04:04.861758 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-09-29 19:04:04.861785 | controller |
2025-09-29 19:04:04.862041 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-09-29 19:04:05.478665 | controller | Monday 29 September 2025  19:04:04 +0000 (0:00:01.065)       0:07:10.483 ******
2025-09-29 19:04:05.478711 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-09-29 19:04:05.991727 | controller |
2025-09-29 19:04:05.991763 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-09-29 19:04:05.991773 | controller | Monday 29 September 2025  19:04:05 +0000 (0:00:00.616)       0:07:11.100 ******
2025-09-29 19:04:05.991786 | controller | changed: [instance]
2025-09-29 19:04:06.334153 | controller |
2025-09-29 19:04:06.334187 | controller | TASK [Write test-node info to file] ********************************************
2025-09-29 19:04:06.334196 | controller | Monday 29 September 2025  19:04:05 +0000 (0:00:00.512)       0:07:11.612 ******
2025-09-29 19:04:06.334206 | controller | changed: [instance]
2025-09-29 19:04:06.702709 | controller |
2025-09-29 19:04:06.702744 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-09-29 19:04:06.702752 | controller | Monday 29 September 2025  19:04:06 +0000 (0:00:00.342)       0:07:11.955 ******
2025-09-29 19:04:06.702762 | controller | changed: [instance]
2025-09-29 19:04:07.059190 | controller |
2025-09-29 19:04:07.059223 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-09-29 19:04:07.059231 | controller | Monday 29 September 2025  19:04:06 +0000 (0:00:00.368)       0:07:12.324 ******
2025-09-29 19:04:07.059241 | controller | changed: [instance]
2025-09-29 19:04:07.402184 | controller |
2025-09-29 19:04:07.402217 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-09-29 19:04:07.402226 | controller | Monday 29 September 2025  19:04:07 +0000 (0:00:00.356)       0:07:12.681 ******
2025-09-29 19:04:07.402236 | controller | changed: [instance]
2025-09-29 19:04:07.735132 | controller |
2025-09-29 19:04:07.735162 | controller | TASK [Write hypervisor info to file] *******************************************
2025-09-29 19:04:07.735170 | controller | Monday 29 September 2025  19:04:07 +0000 (0:00:00.343)       0:07:13.024 ******
2025-09-29 19:04:07.735180 | controller | changed: [instance]
2025-09-29 19:04:07.735204 | controller |
2025-09-29 19:04:07.735213 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-09-29 19:04:07.735347 | controller | Monday 29 September 2025  19:04:07 +0000 (0:00:00.333)       0:07:13.357 ******
2025-09-29 19:04:09.364733 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-09-29 19:04:09.364908 | controller |
2025-09-29 19:04:09.364927 | controller | TASK [Debug the ping example.com result] ***************************************
2025-09-29 19:04:09.405127 | controller | Monday 29 September 2025  19:04:09 +0000 (0:00:01.629)       0:07:14.986 ******
2025-09-29 19:04:09.405158 | controller | ok: [instance] => (item=0) =>
2025-09-29 19:04:09.408365 | controller |   msg: '0'
2025-09-29 19:04:09.408386 | controller | ok: [instance] => (item=['PING example.com(a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8)) 56 data bytes', '64 bytes from a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8): icmp_seq=1 ttl=44 time=40.0 ms', '64 bytes from a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8): icmp_seq=2 ttl=44 time=40.0 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 39.967/39.991/40.015/0.024 ms']) =>
2025-09-29 19:04:09.408398 | controller |   msg:
2025-09-29 19:04:09.468980 | controller |   - PING example.com(a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8)) 56 data bytes
2025-09-29 19:04:09.469010 | controller |   - '64 bytes from a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8): icmp_seq=1 ttl=44 time=40.0 ms'
2025-09-29 19:04:09.469019 | controller |   - '64 bytes from a23-220-75-232.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4be8): icmp_seq=2 ttl=44 time=40.0 ms'
2025-09-29 19:04:09.469025 | controller |   - ''
2025-09-29 19:04:09.469031 | controller |   - '--- example.com ping statistics ---'
2025-09-29 19:04:09.469037 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-09-29 19:04:09.469043 | controller |   - rtt min/avg/max/mdev = 39.967/39.991/40.015/0.024 ms
2025-09-29 19:04:09.469076 | controller | ok: [instance] => (item=[]) =>
2025-09-29 19:04:09.469087 | controller |   msg: []
2025-09-29 19:04:09.469093 | controller |
2025-09-29 19:04:09.469099 | controller | PLAY RECAP *********************************************************************
2025-09-29 19:04:09.469104 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-09-29 19:04:09.469110 | controller |
2025-09-29 19:04:09.469115 | controller | Monday 29 September 2025  19:04:09 +0000 (0:00:00.040)       0:07:15.027 ******
2025-09-29 19:04:09.469121 | controller | ===============================================================================
2025-09-29 19:04:09.469126 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 290.26s
2025-09-29 19:04:09.469131 | controller | Wait for test node to be reachable via ssh ----------------------------- 26.67s
2025-09-29 19:04:09.469137 | controller | Download latest image -------------------------------------------------- 23.09s
2025-09-29 19:04:09.469148 | controller | Wait a little to let the test instance boot. --------------------------- 20.03s
2025-09-29 19:04:09.469154 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir -------------- 10.13s
2025-09-29 19:04:09.469166 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.25s
2025-09-29 19:04:09.469172 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.18s
2025-09-29 19:04:09.469177 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.42s
2025-09-29 19:04:09.469183 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.58s
2025-09-29 19:04:09.469188 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.40s
2025-09-29 19:04:09.469193 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.63s
2025-09-29 19:04:09.469199 | controller | discover_latest_image : Get latest image -------------------------------- 1.58s
2025-09-29 19:04:09.469204 | controller | config_drive : Install required RPM packages ---------------------------- 1.34s
2025-09-29 19:04:09.469210 | controller | config_drive : Install required RPM packages ---------------------------- 1.28s
2025-09-29 19:04:09.469216 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.15s
2025-09-29 19:04:09.469221 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.15s
2025-09-29 19:04:09.469226 | controller | Grab some info from the test node --------------------------------------- 1.07s
2025-09-29 19:04:09.469232 | controller | Grab some info from the nat64 appliance --------------------------------- 1.07s
2025-09-29 19:04:09.469237 | controller | Restart firewalld.service ----------------------------------------------- 0.96s
2025-09-29 19:04:09.469242 | controller | nat64_appliance : Restart firewalld.service ----------------------------- 0.89s
2025-09-29 19:04:09.469252 | controller | INFO     Running default > cleanup
2025-09-29 19:04:09.918504 | controller |
2025-09-29 19:04:10.851967 | controller | PLAY [Cleanup] *****************************************************************
2025-09-29 19:04:10.852004 | controller |
2025-09-29 19:04:10.852014 | controller | TASK [Gathering Facts] *********************************************************
2025-09-29 19:04:10.852021 | controller | Monday 29 September 2025  19:04:09 +0000 (0:00:00.048)       0:00:00.048 ******
2025-09-29 19:04:10.852033 | controller | ok: [instance]
2025-09-29 19:04:11.411792 | controller |
2025-09-29 19:04:11.411822 | controller | TASK [Destroy the test-node] ***************************************************
2025-09-29 19:04:11.411831 | controller | Monday 29 September 2025  19:04:10 +0000 (0:00:00.934)       0:00:00.982 ******
2025-09-29 19:04:11.411841 | controller | ok: [instance]
2025-09-29 19:04:11.639390 | controller |
2025-09-29 19:04:11.639443 | controller | TASK [Undefine the test-node] **************************************************
2025-09-29 19:04:11.639452 | controller | Monday 29 September 2025  19:04:11 +0000 (0:00:00.559)       0:00:01.542 ******
2025-09-29 19:04:11.639462 | controller | ok: [instance]
2025-09-29 19:04:11.998215 | controller |
2025-09-29 19:04:11.998247 | controller | TASK [Destroy the test network] ************************************************
2025-09-29 19:04:11.998256 | controller | Monday 29 September 2025  19:04:11 +0000 (0:00:00.227)       0:00:01.770 ******
2025-09-29 19:04:11.998267 | controller | ok: [instance]
2025-09-29 19:04:11.998473 | controller |
2025-09-29 19:04:11.998506 | controller | TASK [Undefine the test network] ***********************************************
2025-09-29 19:04:12.218504 | controller | Monday 29 September 2025  19:04:11 +0000 (0:00:00.359)       0:00:02.129 ******
2025-09-29 19:04:12.218539 | controller | ok: [instance]
2025-09-29 19:04:12.250763 | controller |
2025-09-29 19:04:12.250785 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-09-29 19:04:12.250794 | controller | Monday 29 September 2025  19:04:12 +0000 (0:00:00.219)       0:00:02.349 ******
2025-09-29 19:04:12.250805 | controller |
2025-09-29 19:04:12.556453 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-09-29 19:04:12.556491 | controller | Monday 29 September 2025  19:04:12 +0000 (0:00:00.032)       0:00:02.382 ******
2025-09-29 19:04:12.556503 | controller | changed: [instance]
2025-09-29 19:04:12.837124 | controller |
2025-09-29 19:04:12.837154 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-09-29 19:04:12.837163 | controller | Monday 29 September 2025  19:04:12 +0000 (0:00:00.305)       0:00:02.687 ******
2025-09-29 19:04:12.837178 | controller | ok: [instance]
2025-09-29 19:04:12.837225 | controller |
2025-09-29 19:04:12.837234 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-09-29 19:04:12.837242 | controller | Monday 29 September 2025  19:04:12 +0000 (0:00:00.280)       0:00:02.968 ******
2025-09-29 19:04:13.058968 | controller | ok: [instance]
2025-09-29 19:04:13.708936 | controller |
2025-09-29 19:04:13.708975 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-09-29 19:04:13.708984 | controller | Monday 29 September 2025  19:04:13 +0000 (0:00:00.221)       0:00:03.190 ******
2025-09-29 19:04:13.708995 | controller | ok: [instance]
2025-09-29 19:04:13.945720 | controller |
2025-09-29 19:04:13.945752 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-09-29 19:04:13.945760 | controller | Monday 29 September 2025  19:04:13 +0000 (0:00:00.649)       0:00:03.839 ******
2025-09-29 19:04:13.945770 | controller | ok: [instance]
2025-09-29 19:04:14.726975 | controller |
2025-09-29 19:04:14.727015 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-09-29 19:04:14.727024 | controller | Monday 29 September 2025  19:04:13 +0000 (0:00:00.236)       0:00:04.076 ******
2025-09-29 19:04:14.727034 | controller | ok: [instance] => (item=nat64-net-v4)
2025-09-29 19:04:15.198091 | controller | ok: [instance] => (item=nat64-net-v6)
2025-09-29 19:04:15.198125 | controller |
2025-09-29 19:04:15.198133 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-09-29 19:04:15.198139 | controller | Monday 29 September 2025  19:04:14 +0000 (0:00:00.781)       0:00:04.857 ******
2025-09-29 19:04:15.198149 | controller | ok: [instance] => (item=nat64-net-v4)
2025-09-29 19:04:15.244911 | controller | ok: [instance] => (item=nat64-net-v6)
2025-09-29 19:04:15.244945 | controller |
2025-09-29 19:04:15.244953 | controller | PLAY RECAP *********************************************************************
2025-09-29 19:04:15.244960 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-09-29 19:04:15.244966 | controller |
2025-09-29 19:04:15.244971 | controller | Monday 29 September 2025  19:04:15 +0000 (0:00:00.469)       0:00:05.327 ******
2025-09-29 19:04:15.244977 | controller | ===============================================================================
2025-09-29 19:04:15.244983 | controller | Gathering Facts --------------------------------------------------------- 0.93s
2025-09-29 19:04:15.244988 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.78s
2025-09-29 19:04:15.244993 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.65s
2025-09-29 19:04:15.244999 | controller | Destroy the test-node --------------------------------------------------- 0.56s
2025-09-29 19:04:15.245004 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.47s
2025-09-29 19:04:15.245009 | controller | Destroy the test network ------------------------------------------------ 0.36s
2025-09-29 19:04:15.245015 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.31s
2025-09-29 19:04:15.245020 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.28s
2025-09-29 19:04:15.245025 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.24s
2025-09-29 19:04:15.245031 | controller | Undefine the test-node -------------------------------------------------- 0.23s
2025-09-29 19:04:15.245036 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.22s
2025-09-29 19:04:15.245041 | controller | Undefine the test network ----------------------------------------------- 0.22s
2025-09-29 19:04:15.245047 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-09-29 19:04:15.245078 | controller | INFO     Writing /tmp/report.html report.
2025-09-29 19:04:15.576512 | [controller] Waiting on logger
2025-09-29 19:04:20.722322 | [controller] Waiting on logger
2025-09-29 19:04:31.154568 | [controller] Waiting on logger
2025-09-29 19:04:41.586354 | [controller] Waiting on logger
2025-09-29 19:04:45.336939 | [Zuul] Log Stream did not terminate
2025-09-29 19:04:45.337094 | controller | changed
2025-09-29 19:04:45.367159 | 
2025-09-29 19:04:45.367232 | PLAY RECAP
2025-09-29 19:04:45.367284 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-29 19:04:45.367310 | 
2025-09-29 19:04:45.463329 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-09-29 19:04:45.469104 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-29 19:04:46.024058 | 
2025-09-29 19:04:46.024176 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-09-29 19:04:46.044658 | 
2025-09-29 19:04:46.044773 | TASK [Filter out host if needed]
2025-09-29 19:04:46.053550 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-09-29 19:04:46.058064 | 
2025-09-29 19:04:46.058136 | TASK [Ensure file is present]
2025-09-29 19:04:46.412555 | controller | ok
2025-09-29 19:04:46.419098 | 
2025-09-29 19:04:46.419166 | TASK [Manage molecule report file]
2025-09-29 19:04:46.441639 | [controller] Waiting on logger
2025-09-29 19:04:55.794432 | [controller] Waiting on logger
2025-09-29 19:05:06.226356 | [controller] Waiting on logger
2025-09-29 19:05:15.607190 | [controller] Waiting on logger
2025-09-29 19:05:16.783539 | [Zuul] Log Stream did not terminate
2025-09-29 19:05:16.783705 | controller | changed
2025-09-29 19:05:16.789333 | 
2025-09-29 19:05:16.789409 | TASK [Check if we get ci-framework-data basedir]
2025-09-29 19:05:16.980387 | controller | ok
2025-09-29 19:05:16.985801 | 
2025-09-29 19:05:16.985881 | TASK [Create ci-framework-data log directory for zuul]
2025-09-29 19:05:17.330951 | controller | changed
2025-09-29 19:05:17.336783 | 
2025-09-29 19:05:17.336851 | TASK [Copy ci-framework interesting files]
2025-09-29 19:05:22.367182 | controller | changed
2025-09-29 19:05:22.373097 | 
2025-09-29 19:05:22.373172 | TASK [Get SELinux listing]
2025-09-29 19:05:22.417566 | [controller] Waiting on logger
2025-09-29 19:05:31.762261 | [controller] Waiting on logger
2025-09-29 19:05:42.194328 | [controller] Waiting on logger
2025-09-29 19:05:52.626341 | [controller] Waiting on logger
2025-09-29 19:05:52.636482 | [Zuul] Log Stream did not terminate
2025-09-29 19:05:52.636638 | controller | changed
2025-09-29 19:05:52.642281 | 
2025-09-29 19:05:52.642353 | TASK [Generate log index]
2025-09-29 19:05:53.327060 | controller | changed
2025-09-29 19:05:53.332525 | 
2025-09-29 19:05:53.332615 | TASK [Get some env related data]
2025-09-29 19:05:58.359400 | controller | changed
2025-09-29 19:05:58.365879 | 
2025-09-29 19:05:58.366007 | TASK [Generate list of logs to collect in home directory]
2025-09-29 19:05:58.700219 | controller | ok: All paths examined
2025-09-29 19:05:58.705960 | 
2025-09-29 19:05:58.706063 | LOOP [Copy logs from home directory]
2025-09-29 19:05:59.080417 | controller | changed:
2025-09-29 19:05:59.080558 | controller | {
2025-09-29 19:05:59.080587 | controller |   "atime": 1759172024.5140457,
2025-09-29 19:05:59.080609 | controller |   "ctime": 1759172042.1572692,
2025-09-29 19:05:59.080629 | controller |   "dev": 64513,
2025-09-29 19:05:59.080647 | controller |   "gid": 1000,
2025-09-29 19:05:59.080666 | controller |   "gr_name": "zuul",
2025-09-29 19:05:59.080684 | controller |   "inode": 4330687,
2025-09-29 19:05:59.080701 | controller |   "isblk": false,
2025-09-29 19:05:59.080717 | controller |   "ischr": false,
2025-09-29 19:05:59.080733 | controller |   "isdir": false,
2025-09-29 19:05:59.080751 | controller |   "isfifo": false,
2025-09-29 19:05:59.080768 | controller |   "isgid": false,
2025-09-29 19:05:59.080788 | controller |   "islnk": false,
2025-09-29 19:05:59.080805 | controller |   "isreg": true,
2025-09-29 19:05:59.080822 | controller |   "issock": false,
2025-09-29 19:05:59.080838 | controller |   "isuid": false,
2025-09-29 19:05:59.080853 | controller |   "mode": "0644",
2025-09-29 19:05:59.080868 | controller |   "mtime": 1759172042.1572692,
2025-09-29 19:05:59.080884 | controller |   "nlink": 1,
2025-09-29 19:05:59.080899 | controller |   "path": "/home/zuul/ansible.log",
2025-09-29 19:05:59.080941 | controller |   "pw_name": "zuul",
2025-09-29 19:05:59.080962 | controller |   "rgrp": true,
2025-09-29 19:05:59.080979 | controller |   "roth": true,
2025-09-29 19:05:59.080995 | controller |   "rusr": true,
2025-09-29 19:05:59.081011 | controller |   "size": 6749,
2025-09-29 19:05:59.081025 | controller |   "uid": 1000,
2025-09-29 19:05:59.081040 | controller |   "wgrp": false,
2025-09-29 19:05:59.081055 | controller |   "woth": false,
2025-09-29 19:05:59.081070 | controller |   "wusr": true,
2025-09-29 19:05:59.081085 | controller |   "xgrp": false,
2025-09-29 19:05:59.081100 | controller |   "xoth": false,
2025-09-29 19:05:59.081114 | controller |   "xusr": false
2025-09-29 19:05:59.081130 | controller | }
2025-09-29 19:05:59.093137 | 
2025-09-29 19:05:59.093275 | TASK [Copy crio stats log file]
2025-09-29 19:05:59.117432 | controller | skipping: Conditional result was False
2025-09-29 19:05:59.128512 | 
2025-09-29 19:05:59.128585 | TASK [Get SELinux related data]
2025-09-29 19:05:59.150980 | [controller] Waiting on logger
2025-09-29 19:06:03.058366 | [controller] Waiting on logger
2025-09-29 19:06:04.257278 | controller | ERROR
2025-09-29 19:06:04.257445 | controller | {
2025-09-29 19:06:04.257482 | controller |   "delta": "0:00:00.008290",
2025-09-29 19:06:04.257505 | controller |   "end": "2025-09-29 19:05:59.336550",
2025-09-29 19:06:04.257524 | controller |   "msg": "non-zero return code",
2025-09-29 19:06:04.257543 | controller |   "rc": 1,
2025-09-29 19:06:04.257560 | controller |   "start": "2025-09-29 19:05:59.328260"
2025-09-29 19:06:04.257579 | controller | }
2025-09-29 19:06:04.257605 | controller | ERROR: Ignoring Errors
2025-09-29 19:06:04.262897 | 
2025-09-29 19:06:04.262984 | TASK [Create system configuration directory]
2025-09-29 19:06:04.464940 | controller | changed
2025-09-29 19:06:04.470240 | 
2025-09-29 19:06:04.470322 | TASK [Get some of the system configurations]
2025-09-29 19:06:07.603228 | [controller] Waiting on logger
2025-09-29 19:06:18.582861 | [controller] Waiting on logger
2025-09-29 19:06:29.363559 | [controller] Waiting on logger
2025-09-29 19:06:34.743443 | [Zuul] Log Stream did not terminate
2025-09-29 19:06:34.743600 | controller | changed
2025-09-29 19:06:34.748664 | 
2025-09-29 19:06:34.748732 | TASK [Copy generated documentation if available]
2025-09-29 19:06:34.772751 | controller | skipping: Conditional result was False
2025-09-29 19:06:34.779707 | 
2025-09-29 19:06:34.779775 | TASK [Copy generated AsciiDoc documentation if available]
2025-09-29 19:06:34.803107 | controller | skipping: Conditional result was False
2025-09-29 19:06:34.808314 | 
2025-09-29 19:06:34.808382 | TASK [Compress logs bigger than 2MB]
2025-09-29 19:06:34.854274 | [controller] Waiting on logger
2025-09-29 19:06:42.355241 | [controller] Waiting on logger
2025-09-29 19:06:50.724349 | controller | changed
2025-09-29 19:06:50.731073 | 
2025-09-29 19:06:50.731179 | TASK [Copy files from workspace on node]
2025-09-29 19:06:50.751043 | controller | ok
2025-09-29 19:06:50.776104 | 
2025-09-29 19:06:50.776208 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-29 19:06:50.790012 | controller | skipping: Conditional result was False
2025-09-29 19:06:50.796486 | 
2025-09-29 19:06:50.796558 | TASK [fetch-output : Set log path for single node]
2025-09-29 19:06:50.826028 | controller | ok
2025-09-29 19:06:50.830797 | 
2025-09-29 19:06:50.830860 | LOOP [fetch-output : Ensure local output dirs]
2025-09-29 19:06:51.044728 | controller -> localhost | ok: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/logs"
2025-09-29 19:06:51.044991 | controller -> localhost | changed: All items complete
2025-09-29 19:06:51.045023 | 
2025-09-29 19:06:51.242705 | controller -> localhost | changed: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/artifacts"
2025-09-29 19:06:51.439619 | controller -> localhost | changed: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/docs"
2025-09-29 19:06:51.450209 | 
2025-09-29 19:06:51.450302 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-29 19:06:52.047369 | controller | changed:
2025-09-29 19:06:52.047549 | controller | .d..t...... ./
2025-09-29 19:06:52.047582 | controller | >f+++++++++ README.html
2025-09-29 19:06:52.047605 | controller | >f+++++++++ ansible-execution.log
2025-09-29 19:06:52.047628 | controller | >f+++++++++ ansible.log
2025-09-29 19:06:52.047647 | controller | >f+++++++++ dmesg.log
2025-09-29 19:06:52.047665 | controller | >f+++++++++ installed-pkgs.log
2025-09-29 19:06:52.047683 | controller | >f+++++++++ python.log
2025-09-29 19:06:52.047700 | controller | >f+++++++++ registries.conf
2025-09-29 19:06:52.047717 | controller | >f+++++++++ report.html
2025-09-29 19:06:52.047733 | controller | >f+++++++++ selinux-denials.log
2025-09-29 19:06:52.047749 | controller | >f+++++++++ selinux-listing.log
2025-09-29 19:06:52.047764 | controller | cd+++++++++ ci-framework-data/
2025-09-29 19:06:52.047779 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-09-29 19:06:52.047794 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-09-29 19:06:52.047809 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-09-29 19:06:52.047823 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-09-29 19:06:52.047839 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-09-29 19:06:52.047854 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-09-29 19:06:52.047869 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/4010801f-e802-5928-880a-2ce4a5f4d91b/
2025-09-29 19:06:52.048108 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/4010801f-e802-5928-880a-2ce4a5f4d91b/meta-data
2025-09-29 19:06:52.048160 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/4010801f-e802-5928-880a-2ce4a5f4d91b/network-config
2025-09-29 19:06:52.048184 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/4010801f-e802-5928-880a-2ce4a5f4d91b/user-data
2025-09-29 19:06:52.048203 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7b7b6ebf-d559-58cb-8258-b15d2e2b84ed/
2025-09-29 19:06:52.048220 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7b7b6ebf-d559-58cb-8258-b15d2e2b84ed/meta-data
2025-09-29 19:06:52.048244 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7b7b6ebf-d559-58cb-8258-b15d2e2b84ed/network-config
2025-09-29 19:06:52.048263 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/7b7b6ebf-d559-58cb-8258-b15d2e2b84ed/user-data
2025-09-29 19:06:52.048280 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-09-29 19:06:52.048296 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-09-29 19:06:52.048311 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-09-29 19:06:52.048327 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-09-29 19:06:52.048344 | controller | cd+++++++++ ci-framework-data/logs/
2025-09-29 19:06:52.048359 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-09-29 19:06:52.048375 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-09-29 19:06:52.048389 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-09-29 19:06:52.048404 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-09-29 19:06:52.048418 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-09-29 19:06:52.048432 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-09-29 19:06:52.048446 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-09-29 19:06:52.048460 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-09-29 19:06:52.048473 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-09-29 19:06:52.048486 | controller | cd+++++++++ registries.conf.d/
2025-09-29 19:06:52.048500 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-09-29 19:06:52.048515 | controller | cd+++++++++ system-config/
2025-09-29 19:06:52.048529 | controller | cd+++++++++ system-config/libvirt/
2025-09-29 19:06:52.048543 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-09-29 19:06:52.048558 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-09-29 19:06:52.048572 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-09-29 19:06:52.048587 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-09-29 19:06:52.048602 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-09-29 19:06:52.048617 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-09-29 19:06:52.048631 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-09-29 19:06:52.048645 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-09-29 19:06:52.048659 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-09-29 19:06:52.048674 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-09-29 19:06:52.048689 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-09-29 19:06:52.048704 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-09-29 19:06:52.048718 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-09-29 19:06:52.048731 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-09-29 19:06:52.048745 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-09-29 19:06:52.048759 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-09-29 19:06:52.082283 | [controller] Waiting on logger
2025-09-29 19:06:52.418240 | controller | changed: .d..t...... ./
2025-09-29 19:06:52.817263 | controller | changed: .d..t...... ./
2025-09-29 19:06:52.839598 | 
2025-09-29 19:06:52.839710 | TASK [Return artifact to Zuul]
2025-09-29 19:06:52.868834 | controller | ok
2025-09-29 19:06:52.888548 | 
2025-09-29 19:06:52.888617 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-09-29 19:06:52.888723 | 
2025-09-29 19:06:52.888757 | PLAY RECAP
2025-09-29 19:06:52.888801 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-09-29 19:06:52.888822 | 
2025-09-29 19:06:52.976105 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-09-29 19:06:52.976991 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-29 19:06:53.567734 | 
2025-09-29 19:06:53.567888 | PLAY [all]
2025-09-29 19:06:53.593770 | 
2025-09-29 19:06:53.593982 | TASK [include_role : fetch-output]
2025-09-29 19:06:53.627152 | controller | ok
2025-09-29 19:06:53.648633 | 
2025-09-29 19:06:53.648803 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-29 19:06:53.706994 | controller | skipping: Conditional result was False
2025-09-29 19:06:53.714716 | 
2025-09-29 19:06:53.714842 | TASK [fetch-output : Set log path for single node]
2025-09-29 19:06:53.759147 | controller | ok
2025-09-29 19:06:53.765104 | 
2025-09-29 19:06:53.765210 | LOOP [fetch-output : Ensure local output dirs]
2025-09-29 19:06:54.202382 | controller -> localhost | ok: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/logs"
2025-09-29 19:06:54.415977 | controller -> localhost | ok: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/artifacts"
2025-09-29 19:06:54.621702 | controller -> localhost | ok: "/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/docs"
2025-09-29 19:06:54.637425 | 
2025-09-29 19:06:54.637557 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-29 19:06:55.232981 | controller | ok
2025-09-29 19:06:55.233181 | controller | ok: All items complete
2025-09-29 19:06:55.233215 | 
2025-09-29 19:06:55.647183 | controller | ok
2025-09-29 19:06:56.036987 | controller | ok
2025-09-29 19:06:56.054592 | 
2025-09-29 19:06:56.054712 | TASK [include_role : fetch-output-openshift]
2025-09-29 19:06:56.068319 | controller | skipping: Conditional result was False
2025-09-29 19:06:56.074386 | 
2025-09-29 19:06:56.074457 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-29 19:06:56.473218 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006426
2025-09-29 19:06:56.669421 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007238
2025-09-29 19:06:56.702681 | 
2025-09-29 19:06:56.702777 | PLAY [all]
2025-09-29 19:06:56.730433 | 
2025-09-29 19:06:56.730510 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-29 19:06:57.152206 | controller | changed
2025-09-29 19:06:57.175204 | 
2025-09-29 19:06:57.175274 | PLAY RECAP
2025-09-29 19:06:57.175318 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-29 19:06:57.175341 | 
2025-09-29 19:06:57.249375 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-29 19:06:57.250191 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-29 19:06:58.045780 | 
2025-09-29 19:06:58.045885 | PLAY [localhost]
2025-09-29 19:06:58.066822 | 
2025-09-29 19:06:58.066942 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-29 19:06:58.388430 | localhost | changed
2025-09-29 19:06:58.393082 | 
2025-09-29 19:06:58.393176 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-29 19:06:58.420795 | localhost | ok
2025-09-29 19:06:58.428377 | 
2025-09-29 19:06:58.428485 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-29 19:06:58.749727 | localhost | changed
2025-09-29 19:06:58.760000 | 
2025-09-29 19:06:58.760096 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-29 19:06:59.340698 | localhost | changed
2025-09-29 19:06:59.345647 | 
2025-09-29 19:06:59.345737 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-29 19:06:59.687829 | localhost | Identity added: /var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/tmp/ansible.eftlg5ht (/var/lib/zuul/builds/54a012b4e558421e80af7bc3266b63ac/work/tmp/ansible.eftlg5ht)
2025-09-29 19:06:59.688018 | localhost | ok: Runtime: 0:00:00.006175
2025-09-29 19:06:59.693078 | 
2025-09-29 19:06:59.693160 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-29 19:06:59.913926 | localhost | ok: Runtime: 0:00:00.004320
2025-09-29 19:06:59.918636 | 
2025-09-29 19:06:59.918722 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-29 19:06:59.967854 | localhost | changed
2025-09-29 19:06:59.972158 | 
2025-09-29 19:06:59.972241 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-29 19:07:00.304561 | localhost | changed
2025-09-29 19:07:00.324245 | 
2025-09-29 19:07:00.324314 | PLAY [localhost]
2025-09-29 19:07:00.335833 | 
2025-09-29 19:07:00.335897 | TASK [Generate bulk log download script]
2025-09-29 19:07:00.354404 | localhost | ok
2025-09-29 19:07:00.366024 | 
2025-09-29 19:07:00.366294 | TASK [local-log-download : Check API endpoint is defined]
2025-09-29 19:07:00.395087 | localhost | ok: All assertions passed
2025-09-29 19:07:00.399517 | 
2025-09-29 19:07:00.399584 | TASK [local-log-download : Create download script]
2025-09-29 19:07:00.777793 | localhost -> localhost | changed
2025-09-29 19:07:00.786834 | 
2025-09-29 19:07:00.786941 | TASK [Register quick-download link]
2025-09-29 19:07:00.803895 | localhost | ok
2025-09-29 19:07:00.840596 | 
2025-09-29 19:07:00.840684 | PLAY [logserver.rdoproject.org]
2025-09-29 19:07:00.850382 | 
2025-09-29 19:07:00.850458 | TASK [Set zuul-log-path fact]
2025-09-29 19:07:00.866366 | logserver.rdoproject.org | ok
2025-09-29 19:07:00.875893 | 
2025-09-29 19:07:00.875993 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-29 19:07:00.902342 | logserver.rdoproject.org | ok
2025-09-29 19:07:00.907825 | 
2025-09-29 19:07:00.907893 | TASK [upload-logs : Create log directories]
2025-09-29 19:07:02.648510 | logserver.rdoproject.org | changed
2025-09-29 19:07:02.652051 | 
2025-09-29 19:07:02.653591 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-29 19:07:02.902457 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005919
2025-09-29 19:07:02.908360 | 
2025-09-29 19:07:02.908456 | TASK [upload-logs : Upload logs to log server]
2025-09-29 19:07:04.896612 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-29 19:07:04.902812 | 
2025-09-29 19:07:04.902901 | LOOP [upload-logs : Compress console log and json output]
2025-09-29 19:07:04.948044 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-29 19:07:04.963614 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-29 19:07:04.972180 | 
2025-09-29 19:07:04.972275 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-29 19:07:05.029236 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-29 19:07:05.029459 | 
2025-09-29 19:07:05.029984 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-29 19:07:05.040648 | 
2025-09-29 19:07:05.040756 | LOOP [upload-logs : Upload console log and json output]