2025-10-08 15:43:27.277102 | Job console starting...
2025-10-08 15:43:27.515097 | Updating repositories
2025-10-08 15:43:28.231750 | Preparing job workspace
2025-10-08 15:43:36.009357 | Running Ansible setup...
2025-10-08 15:43:39.952739 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 15:43:40.747872 | 
2025-10-08 15:43:40.747994 | PLAY [localhost]
2025-10-08 15:43:40.763666 | 
2025-10-08 15:43:40.763752 | TASK [Gathering Facts]
2025-10-08 15:43:41.828384 | localhost | ok
2025-10-08 15:43:41.844598 | 
2025-10-08 15:43:41.844755 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-08 15:43:42.224519 | localhost -> localhost | changed
2025-10-08 15:43:42.230155 | 
2025-10-08 15:43:42.230247 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-08 15:43:43.316274 | localhost -> localhost | changed
2025-10-08 15:43:43.334058 | 
2025-10-08 15:43:43.334137 | TASK [Setup log path fact]
2025-10-08 15:43:43.360863 | localhost | ok
2025-10-08 15:43:43.382006 | 
2025-10-08 15:43:43.382112 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 15:43:43.410570 | localhost | ok
2025-10-08 15:43:43.419315 | 
2025-10-08 15:43:43.419405 | TASK [emit-job-header : Print job information]
2025-10-08 15:43:43.464820 | # Job Information
2025-10-08 15:43:43.464974 | Ansible Version: 2.15.12
2025-10-08 15:43:43.465007 | Job: cifmw-molecule-nat64_appliance
2025-10-08 15:43:43.465031 | Pipeline: github-check
2025-10-08 15:43:43.465053 | Executor: ibm-bm4-ze.softwarefactory-project.io
2025-10-08 15:43:43.465072 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3385
2025-10-08 15:43:43.465092 | Log URL (when completed): https://logserver.rdoproject.org/497/rdoproject.org/4976c3651bdd44e3b2e446550411f3c7/
2025-10-08 15:43:43.465112 | Event ID: 32fe2bb0-a45c-11f0-9dbb-741a4abaa18c
2025-10-08 15:43:43.468719 | 
2025-10-08 15:43:43.468785 | LOOP [emit-job-header : Print node information]
2025-10-08 15:43:43.610793 | localhost | ok:
2025-10-08 15:43:43.611064 | localhost | # Node Information
2025-10-08 15:43:43.611106 | localhost | Inventory Hostname: controller
2025-10-08 15:43:43.611136 | localhost | Hostname: np0005477245
2025-10-08 15:43:43.611159 | localhost | Username: zuul
2025-10-08 15:43:43.611181 | localhost | Distro: CentOS 9
2025-10-08 15:43:43.611201 | localhost | Provider: ibm-bm4-nodepool
2025-10-08 15:43:43.611236 | localhost | Region: regionOne
2025-10-08 15:43:43.611256 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-10-08 15:43:43.611277 | localhost | Product Name: OpenStack Compute
2025-10-08 15:43:43.611296 | localhost | Interface IP: 192.168.26.47
2025-10-08 15:43:43.633652 | 
2025-10-08 15:43:43.633783 | PLAY [all]
2025-10-08 15:43:43.640304 | 
2025-10-08 15:43:43.640371 | TASK [Gather network facts]
2025-10-08 15:43:44.001740 | controller | ok
2025-10-08 15:43:44.019033 | 
2025-10-08 15:43:44.019134 | TASK [include_role : start-zuul-console]
2025-10-08 15:43:44.037743 | controller | ok
2025-10-08 15:43:44.055360 | 
2025-10-08 15:43:44.055441 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-08 15:43:44.403097 | controller | ok
2025-10-08 15:43:44.417709 | 
2025-10-08 15:43:44.417780 | TASK [include_role : add-build-sshkey]
2025-10-08 15:43:44.466945 | controller | ok
2025-10-08 15:43:44.496359 | 
2025-10-08 15:43:44.496447 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-08 15:43:44.927399 | controller -> localhost | ok
2025-10-08 15:43:44.932816 | 
2025-10-08 15:43:44.932884 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-08 15:43:44.971068 | controller | ok
2025-10-08 15:43:44.995318 | controller | included: /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-08 15:43:45.011998 | 
2025-10-08 15:43:45.012107 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-08 15:43:45.846930 | controller -> localhost | Generating public/private rsa key pair.
2025-10-08 15:43:45.847138 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/4976c3651bdd44e3b2e446550411f3c7_id_rsa.
2025-10-08 15:43:45.847174 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/4976c3651bdd44e3b2e446550411f3c7_id_rsa.pub.
2025-10-08 15:43:45.847200 | controller -> localhost | The key fingerprint is:
2025-10-08 15:43:45.847234 | controller -> localhost | SHA256:/RfXETLI8iAg41qvy7TZ7gn+4AwE3c3P/4RwuZXqRps zuul-build-sshkey
2025-10-08 15:43:45.847261 | controller -> localhost | The key's randomart image is:
2025-10-08 15:43:45.847284 | controller -> localhost | +---[RSA 3072]----+
2025-10-08 15:43:45.847307 | controller -> localhost | |   o ..   . .o . |
2025-10-08 15:43:45.847328 | controller -> localhost | | ...oo . o o  o .|
2025-10-08 15:43:45.847350 | controller -> localhost | |. .o. o . +    . |
2025-10-08 15:43:45.847373 | controller -> localhost | |. o .  o . o .  o|
2025-10-08 15:43:45.847393 | controller -> localhost | | o   .  S + o . o|
2025-10-08 15:43:45.847412 | controller -> localhost | |.   .    +.*   o |
2025-10-08 15:43:45.847432 | controller -> localhost | | . =     .=oo .  |
2025-10-08 15:43:45.847454 | controller -> localhost | |  B B .  .Eo .   |
2025-10-08 15:43:45.847474 | controller -> localhost | |   O+*   .. .    |
2025-10-08 15:43:45.847494 | controller -> localhost | +----[SHA256]-----+
2025-10-08 15:43:45.847539 | controller -> localhost | ok: Runtime: 0:00:00.208687
2025-10-08 15:43:45.853485 | 
2025-10-08 15:43:45.853615 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-08 15:43:45.903999 | controller | ok
2025-10-08 15:43:45.928747 | controller | included: /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-08 15:43:45.946758 | 
2025-10-08 15:43:45.946832 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-08 15:43:45.984553 | controller | skipping: Conditional result was False
2025-10-08 15:43:45.990463 | 
2025-10-08 15:43:45.990528 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-08 15:43:46.472536 | controller | changed
2025-10-08 15:43:46.477625 | 
2025-10-08 15:43:46.477707 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-08 15:43:46.668958 | controller | ok
2025-10-08 15:43:46.674226 | 
2025-10-08 15:43:46.674312 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-08 15:43:47.275987 | controller | changed
2025-10-08 15:43:47.282041 | 
2025-10-08 15:43:47.282157 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-08 15:43:47.870958 | controller | changed
2025-10-08 15:43:47.876407 | 
2025-10-08 15:43:47.876482 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-08 15:43:47.914352 | controller | skipping: Conditional result was False
2025-10-08 15:43:47.920510 | 
2025-10-08 15:43:47.920588 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-08 15:43:48.430500 | controller -> localhost | changed
2025-10-08 15:43:48.440536 | 
2025-10-08 15:43:48.440605 | TASK [add-build-sshkey : Add back temp key]
2025-10-08 15:43:48.755411 | controller -> localhost | Identity added: /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/4976c3651bdd44e3b2e446550411f3c7_id_rsa (zuul-build-sshkey)
2025-10-08 15:43:48.755592 | controller -> localhost | ok: Runtime: 0:00:00.008076
2025-10-08 15:43:48.763436 | 
2025-10-08 15:43:48.763504 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-08 15:43:49.128379 | controller | ok
2025-10-08 15:43:49.134209 | 
2025-10-08 15:43:49.134293 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-08 15:43:49.158717 | controller | skipping: Conditional result was False
2025-10-08 15:43:49.168595 | 
2025-10-08 15:43:49.168668 | TASK [include_role : validate-host]
2025-10-08 15:43:49.208024 | controller | ok
2025-10-08 15:43:49.239991 | 
2025-10-08 15:43:49.240085 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-08 15:43:49.268017 | controller | ok
2025-10-08 15:43:49.273301 | 
2025-10-08 15:43:49.273368 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-08 15:43:49.482674 | controller -> localhost | ok
2025-10-08 15:43:49.488664 | 
2025-10-08 15:43:49.488732 | TASK [validate-host : Collect information about the host]
2025-10-08 15:43:50.113929 | controller | ok
2025-10-08 15:43:50.122407 | 
2025-10-08 15:43:50.122471 | TASK [validate-host : Sanitize hostname]
2025-10-08 15:43:50.172109 | controller | ok
2025-10-08 15:43:50.177166 | 
2025-10-08 15:43:50.177245 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-08 15:43:50.650341 | controller -> localhost | changed
2025-10-08 15:43:50.656028 | 
2025-10-08 15:43:50.656099 | TASK [validate-host : Collect information about zuul worker]
2025-10-08 15:43:50.998601 | controller | ok
2025-10-08 15:43:51.003209 | 
2025-10-08 15:43:51.003285 | TASK [validate-host : Write out all zuul information for each host]
2025-10-08 15:43:51.402434 | controller -> localhost | changed
2025-10-08 15:43:51.412589 | 
2025-10-08 15:43:51.412658 | TASK [include_role : prepare-workspace-openshift]
2025-10-08 15:43:51.436269 | controller | skipping: Conditional result was False
2025-10-08 15:43:51.441287 | 
2025-10-08 15:43:51.441352 | TASK [include_role : remove-zuul-sshkey]
2025-10-08 15:43:51.454841 | controller | skipping: Conditional result was False
2025-10-08 15:43:51.460687 | 
2025-10-08 15:43:51.460761 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-08 15:43:51.671774 | controller | ok: "logs"
2025-10-08 15:43:51.672024 | controller | ok: All items complete
2025-10-08 15:43:51.672056 | 
2025-10-08 15:43:51.841002 | controller | ok: "artifacts"
2025-10-08 15:43:52.017993 | controller | ok: "docs"
2025-10-08 15:43:52.031415 | 
2025-10-08 15:43:52.031487 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-08 15:43:52.241936 | controller | changed: "logs"
2025-10-08 15:43:52.427178 | controller | changed: "artifacts"
2025-10-08 15:43:52.613786 | controller | changed: "docs"
2025-10-08 15:43:52.637397 | 
2025-10-08 15:43:52.637480 | PLAY RECAP
2025-10-08 15:43:52.637528 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 15:43:52.637559 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 15:43:52.637581 | 
2025-10-08 15:43:52.711592 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-08 15:43:52.712392 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 15:43:53.311716 | 
2025-10-08 15:43:53.311817 | PLAY [all]
2025-10-08 15:43:53.331705 | 
2025-10-08 15:43:53.331780 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 15:43:53.400756 | controller | ok
2025-10-08 15:43:53.405962 | 
2025-10-08 15:43:53.406045 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 15:43:53.741197 | controller | changed
2025-10-08 15:43:53.746838 | 
2025-10-08 15:43:53.746932 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 15:43:54.579521 | controller | changed
2025-10-08 15:43:54.590574 | 
2025-10-08 15:43:54.590681 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-10-08 15:43:54.982833 | controller | changed:
2025-10-08 15:43:54.983010 | controller | {
2025-10-08 15:43:54.983040 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-10-08 15:43:54.983069 | controller | }
2025-10-08 15:43:55.191061 | controller | changed:
2025-10-08 15:43:55.191265 | controller | {
2025-10-08 15:43:55.191305 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-10-08 15:43:55.191330 | controller | }
2025-10-08 15:43:55.384690 | controller | changed:
2025-10-08 15:43:55.384780 | controller | {
2025-10-08 15:43:55.384811 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-10-08 15:43:55.384833 | controller | }
2025-10-08 15:43:55.588507 | controller | changed:
2025-10-08 15:43:55.588594 | controller | {
2025-10-08 15:43:55.588621 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-10-08 15:43:55.588642 | controller | }
2025-10-08 15:43:55.797156 | controller | changed:
2025-10-08 15:43:55.797262 | controller | {
2025-10-08 15:43:55.797291 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-10-08 15:43:55.797312 | controller | }
2025-10-08 15:43:56.023803 | controller | changed:
2025-10-08 15:43:56.024103 | controller | {
2025-10-08 15:43:56.024149 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-10-08 15:43:56.024175 | controller | }
2025-10-08 15:43:56.248396 | controller | changed:
2025-10-08 15:43:56.248480 | controller | {
2025-10-08 15:43:56.248507 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen"
2025-10-08 15:43:56.248528 | controller | }
2025-10-08 15:43:56.462965 | controller | changed:
2025-10-08 15:43:56.463056 | controller | {
2025-10-08 15:43:56.463084 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora"
2025-10-08 15:43:56.463107 | controller | }
2025-10-08 15:43:56.686277 | controller | changed:
2025-10-08 15:43:56.686369 | controller | {
2025-10-08 15:43:56.686397 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-10-08 15:43:56.686418 | controller | }
2025-10-08 15:43:56.911885 | controller | changed:
2025-10-08 15:43:56.911991 | controller | {
2025-10-08 15:43:56.912019 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-10-08 15:43:56.912040 | controller | }
2025-10-08 15:43:57.134098 | controller | changed:
2025-10-08 15:43:57.134192 | controller | {
2025-10-08 15:43:57.134238 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-10-08 15:43:57.134261 | controller | }
2025-10-08 15:43:57.359246 | controller | changed:
2025-10-08 15:43:57.359348 | controller | {
2025-10-08 15:43:57.359375 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-10-08 15:43:57.359397 | controller | }
2025-10-08 15:43:57.585056 | controller | changed:
2025-10-08 15:43:57.585148 | controller | {
2025-10-08 15:43:57.585174 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-10-08 15:43:57.585195 | controller | }
2025-10-08 15:43:57.812029 | controller | changed:
2025-10-08 15:43:57.812128 | controller | {
2025-10-08 15:43:57.812164 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-10-08 15:43:57.812193 | controller | }
2025-10-08 15:43:58.028642 | controller | changed:
2025-10-08 15:43:58.028744 | controller | {
2025-10-08 15:43:58.028774 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-10-08 15:43:58.028794 | controller | }
2025-10-08 15:43:58.253614 | controller | changed:
2025-10-08 15:43:58.253700 | controller | {
2025-10-08 15:43:58.253730 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-10-08 15:43:58.253751 | controller | }
2025-10-08 15:43:58.469510 | controller | changed:
2025-10-08 15:43:58.469595 | controller | {
2025-10-08 15:43:58.469623 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com"
2025-10-08 15:43:58.469646 | controller | }
2025-10-08 15:43:58.684271 | controller | changed:
2025-10-08 15:43:58.684416 | controller | {
2025-10-08 15:43:58.684450 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb"
2025-10-08 15:43:58.684482 | controller | }
2025-10-08 15:43:58.902412 | controller | changed:
2025-10-08 15:43:58.902486 | controller | {
2025-10-08 15:43:58.902513 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-10-08 15:43:58.902534 | controller | }
2025-10-08 15:43:59.124319 | controller | changed:
2025-10-08 15:43:59.124397 | controller | {
2025-10-08 15:43:59.124431 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-10-08 15:43:59.124458 | controller | }
2025-10-08 15:43:59.331591 | controller | changed:
2025-10-08 15:43:59.331670 | controller | {
2025-10-08 15:43:59.331696 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-10-08 15:43:59.331716 | controller | }
2025-10-08 15:43:59.547999 | controller | changed:
2025-10-08 15:43:59.548076 | controller | {
2025-10-08 15:43:59.548103 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-10-08 15:43:59.548123 | controller | }
2025-10-08 15:43:59.769399 | controller | changed:
2025-10-08 15:43:59.769471 | controller | {
2025-10-08 15:43:59.769498 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com"
2025-10-08 15:43:59.769520 | controller | }
2025-10-08 15:43:59.985690 | controller | changed:
2025-10-08 15:43:59.985762 | controller | {
2025-10-08 15:43:59.985788 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-10-08 15:43:59.985809 | controller | }
2025-10-08 15:44:00.200358 | controller | changed:
2025-10-08 15:44:00.200458 | controller | {
2025-10-08 15:44:00.200486 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-10-08 15:44:00.200506 | controller | }
2025-10-08 15:44:00.429384 | controller | changed:
2025-10-08 15:44:00.429470 | controller | {
2025-10-08 15:44:00.429497 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-10-08 15:44:00.429518 | controller | }
2025-10-08 15:44:00.454506 | 
2025-10-08 15:44:00.454590 | TASK [Set timezone to UTC]
2025-10-08 15:44:00.884044 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-10-08 15:44:00.890798 | 
2025-10-08 15:44:00.890889 | TASK [Create nodepool directory]
2025-10-08 15:44:01.102619 | controller | changed
2025-10-08 15:44:01.108420 | 
2025-10-08 15:44:01.108507 | TASK [Create nodepool sub_nodes file]
2025-10-08 15:44:01.672145 | controller | changed
2025-10-08 15:44:01.677123 | 
2025-10-08 15:44:01.677214 | TASK [Create nodepool sub_nodes_private file]
2025-10-08 15:44:02.251176 | controller | changed
2025-10-08 15:44:02.256989 | 
2025-10-08 15:44:02.257072 | LOOP [Populate nodepool sub_nodes file]
2025-10-08 15:44:02.294548 | 
2025-10-08 15:44:02.294696 | LOOP [Populate nodepool sub_nodes_private file]
2025-10-08 15:44:02.324438 | 
2025-10-08 15:44:02.324565 | TASK [Create nodepool primary file]
2025-10-08 15:44:02.348324 | controller | skipping: Conditional result was False
2025-10-08 15:44:02.353722 | 
2025-10-08 15:44:02.353804 | TASK [Create nodepool node_private for this node]
2025-10-08 15:44:02.930619 | controller | changed
2025-10-08 15:44:02.937572 | 
2025-10-08 15:44:02.937638 | LOOP [Copy ssh keys to nodepool directory]
2025-10-08 15:44:03.280420 | controller | ok: Item: id_rsa Runtime: 0:00:00.007779
2025-10-08 15:44:03.280596 | 
2025-10-08 15:44:03.472492 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006248
2025-10-08 15:44:03.486871 | 
2025-10-08 15:44:03.486992 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-10-08 15:44:04.085456 | controller | changed
2025-10-08 15:44:04.090862 | 
2025-10-08 15:44:04.091014 | TASK [Validate sudoers config after edits]
2025-10-08 15:44:04.320712 | controller | /etc/sudoers: parsed OK
2025-10-08 15:44:04.320773 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-10-08 15:44:04.320783 | controller | /etc/sudoers.d/zuul: parsed OK
2025-10-08 15:44:04.320789 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-10-08 15:44:04.619965 | controller | ok: Runtime: 0:00:00.005727
2025-10-08 15:44:04.625476 | 
2025-10-08 15:44:04.625545 | TASK [Show the environment passed in to job shell scripts]
2025-10-08 15:44:04.832282 | controller | SHELL=/bin/bash
2025-10-08 15:44:04.832326 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-10-08 15:44:04.832336 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-10-08 15:44:04.832344 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/85/3385/f8a3c957fc51bd892aee4b1f66ce262682944823
2025-10-08 15:44:04.832350 | controller | PWD=/home/zuul
2025-10-08 15:44:04.832369 | controller | ZUUL_PIPELINE=github-check
2025-10-08 15:44:04.832378 | controller | LOGNAME=zuul
2025-10-08 15:44:04.832384 | controller | XDG_SESSION_TYPE=tty
2025-10-08 15:44:04.832389 | controller | _=/usr/bin/env
2025-10-08 15:44:04.832394 | controller | MOTD_SHOWN=pam
2025-10-08 15:44:04.832400 | controller | HOME=/home/zuul
2025-10-08 15:44:04.832405 | controller | LANG=en_US.UTF-8
2025-10-08 15:44:04.832410 | controller | SSH_CONNECTION=192.168.26.12 33488 192.168.26.47 22
2025-10-08 15:44:04.832416 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET
2025-10-08 15:44:04.832455 | controller | ZUUL_CHANGE_IDS=3385,f8a3c957fc51bd892aee4b1f66ce262682944823
2025-10-08 15:44:04.832463 | controller | WORKSPACE=/home/zuul/workspace
2025-10-08 15:44:04.832469 | controller | XDG_SESSION_CLASS=user
2025-10-08 15:44:04.832475 | controller | SELINUX_ROLE_REQUESTED=
2025-10-08 15:44:04.832480 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-10-08 15:44:04.832485 | controller | USER=zuul
2025-10-08 15:44:04.832491 | controller | ZUUL_VOTING=True
2025-10-08 15:44:04.832496 | controller | BUILD_TIMEOUT=1800000
2025-10-08 15:44:04.832501 | controller | SELINUX_USE_CURRENT_RANGE=
2025-10-08 15:44:04.832506 | controller | SHLVL=1
2025-10-08 15:44:04.832512 | controller | ZUUL_PATCHSET=f8a3c957fc51bd892aee4b1f66ce262682944823
2025-10-08 15:44:04.832517 | controller | XDG_SESSION_ID=1
2025-10-08 15:44:04.832523 | controller | ZUUL_BRANCH=main
2025-10-08 15:44:04.832528 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-10-08 15:44:04.832533 | controller | SSH_CLIENT=192.168.26.12 33488 22
2025-10-08 15:44:04.832541 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-10-08 15:44:04.832546 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-10-08 15:44:04.832552 | controller | which_declare=declare -f
2025-10-08 15:44:04.832557 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-10-08 15:44:04.832563 | controller | SELINUX_LEVEL_REQUESTED=
2025-10-08 15:44:04.832568 | controller | ZUUL_CHANGE=3385
2025-10-08 15:44:04.832573 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-10-08 15:44:04.832579 | controller | ZUUL_UUID=4976c3651bdd44e3b2e446550411f3c7
2025-10-08 15:44:04.832584 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-10-08 15:44:04.832589 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-10-08 15:44:04.832595 | controller | }
2025-10-08 15:44:05.153262 | controller | ok: Runtime: 0:00:00.005848
2025-10-08 15:44:05.159050 | 
2025-10-08 15:44:05.159117 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-10-08 15:44:05.172458 | controller | skipping: Conditional result was False
2025-10-08 15:44:05.178233 | 
2025-10-08 15:44:05.178305 | TASK [Symlink /home/zuul-worker/workspace]
2025-10-08 15:44:05.704577 | controller | skipping: Conditional result was False
2025-10-08 15:44:05.711827 | 
2025-10-08 15:44:05.711951 | TASK [Ensure legacy workspace directory]
2025-10-08 15:44:05.915449 | controller | changed
2025-10-08 15:44:05.933528 | 
2025-10-08 15:44:05.933602 | PLAY RECAP
2025-10-08 15:44:05.933651 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-08 15:44:05.933701 | 
2025-10-08 15:44:06.019800 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-10-08 15:44:06.020562 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 15:44:06.544346 | 
2025-10-08 15:44:06.544473 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-10-08 15:44:06.568923 | 
2025-10-08 15:44:06.569003 | TASK [Create zuul-output directory]
2025-10-08 15:44:06.903320 | controller | changed
2025-10-08 15:44:06.908652 | 
2025-10-08 15:44:06.908726 | TASK [Slurp Zuul inventory test]
2025-10-08 15:44:07.185762 | controller -> localhost | ok
2025-10-08 15:44:07.192383 | 
2025-10-08 15:44:07.192472 | TASK [Save zuul inventory]
2025-10-08 15:44:07.955176 | controller | changed
2025-10-08 15:44:07.960636 | 
2025-10-08 15:44:07.960725 | TASK [Save zuul vars without the change_message]
2025-10-08 15:44:08.551519 | controller | changed
2025-10-08 15:44:08.580161 | 
2025-10-08 15:44:08.580278 | PLAY RECAP
2025-10-08 15:44:08.580324 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-08 15:44:08.580348 | 
2025-10-08 15:44:08.668892 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-10-08 15:44:08.669725 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 15:44:09.283767 | 
2025-10-08 15:44:09.283869 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-10-08 15:44:09.305436 | 
2025-10-08 15:44:09.305516 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-10-08 15:44:09.323998 | controller | ok
2025-10-08 15:44:09.341747 | 
2025-10-08 15:44:09.341861 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-10-08 15:44:09.365878 | controller | skipping: Conditional result was False
2025-10-08 15:44:09.372071 | 
2025-10-08 15:44:09.372174 | TASK [mirror-info-fork : Create /etc/ci]
2025-10-08 15:44:09.707075 | controller | ok
2025-10-08 15:44:09.713262 | 
2025-10-08 15:44:09.713370 | TASK [mirror-info-fork : Install ci_mirror script]
2025-10-08 15:44:10.364842 | controller | ok
2025-10-08 15:44:10.376864 | 
2025-10-08 15:44:10.376979 | TASK [Prepare workspace]
2025-10-08 15:44:10.396695 | controller | ok
2025-10-08 15:44:10.415970 | 
2025-10-08 15:44:10.416081 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-08 15:44:10.730214 | controller | ok
2025-10-08 15:44:10.737179 | 
2025-10-08 15:44:10.737284 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-08 15:44:12.745163 | controller | Output suppressed because no_log was given
2025-10-08 15:44:12.754305 | 
2025-10-08 15:44:12.754370 | LOOP [Create zuul-output directory]
2025-10-08 15:44:12.956009 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-10-08 15:44:13.124729 | controller | ok: "/home/zuul/zuul-output/logs"
2025-10-08 15:44:13.141525 | 
2025-10-08 15:44:13.141617 | TASK [Install required packages]
2025-10-08 15:45:18.208741 | controller | changed
2025-10-08 15:45:18.215173 | 
2025-10-08 15:45:18.215285 | TASK [Install venv]
2025-10-08 15:46:20.385043 | controller | changed
2025-10-08 15:46:20.415249 | 
2025-10-08 15:46:20.415351 | PLAY RECAP
2025-10-08 15:46:20.415395 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 15:46:20.415419 | 
2025-10-08 15:46:20.516138 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-10-08 15:46:20.517093 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 15:46:21.110363 | 
2025-10-08 15:46:21.110473 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-10-08 15:46:21.132424 | 
2025-10-08 15:46:21.132527 | TASK [Gather required facts]
2025-10-08 15:46:21.642609 | controller | ok
2025-10-08 15:46:21.648458 | 
2025-10-08 15:46:21.648541 | TASK [Load environment var if instructed to]
2025-10-08 15:46:21.684055 | controller | skipping: Conditional result was False
2025-10-08 15:46:21.689636 | 
2025-10-08 15:46:21.689717 | TASK [Ensure group_vars dir exists]
2025-10-08 15:46:22.075615 | controller | ok
2025-10-08 15:46:22.083854 | 
2025-10-08 15:46:22.083963 | TASK [Run molecule]
2025-10-08 15:46:23.053989 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-10-08 15:46:23.127190 | controller | INFO     Performing prerun with role_name_check=0...
2025-10-08 15:46:39.728457 | controller | WARNING  Another version of '@NAMESPACE@.@NAME@' 3.1.4 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 3.1.4 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.728898 | controller | WARNING  Another version of 'ansible.netcommon' 7.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 7.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.729390 | controller | WARNING  Another version of 'ansible.posix' 1.6.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.6.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.729826 | controller | WARNING  Another version of 'ansible.utils' 5.1.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.1.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.730298 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+f8a3c957 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+f8a3c957 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.730765 | controller | WARNING  Another version of 'cisco.ios' 9.0.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.0.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.731206 | controller | WARNING  Another version of 'community.crypto' 2.22.3 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.22.3 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.731669 | controller | WARNING  Another version of 'community.general' 10.0.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 10.0.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.732146 | controller | WARNING  Another version of 'community.libvirt' 1.3.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.3.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.732588 | controller | WARNING  Another version of 'community.okd' 4.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 4.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.733021 | controller | WARNING  Another version of 'containers.podman' 1.16.2 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.16.2 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.733490 | controller | WARNING  Another version of 'junipernetworks.junos' 9.1.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 9.1.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.733935 | controller | WARNING  Another version of 'kubernetes.core' 5.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 5.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.734377 | controller | WARNING  Another version of 'mellanox.onyx' 1.0.0 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.734837 | controller | WARNING  Another version of 'openstack.config_template' 2.1.1 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 2.1.1 (/home/zuul/.ansible/collections/ansible_collections).
2025-10-08 15:46:39.744757 | controller | INFO     Running default > prepare
2025-10-08 15:46:40.435330 | controller |
2025-10-08 15:46:40.435463 | controller | PLAY [Prepare] *****************************************************************
2025-10-08 15:46:40.435591 | controller |
2025-10-08 15:46:40.435733 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 15:46:40.435842 | controller | Wednesday 08 October 2025  15:46:40 +0000 (0:00:00.020)       0:00:00.020 *****
2025-10-08 15:46:41.265061 | controller | ok: [instance]
2025-10-08 15:46:41.265115 | controller |
2025-10-08 15:46:41.265228 | controller | TASK [Create custom basedir] ***************************************************
2025-10-08 15:46:41.265332 | controller | Wednesday 08 October 2025  15:46:41 +0000 (0:00:00.830)       0:00:00.850 *****
2025-10-08 15:46:41.570005 | controller | ok: [instance]
2025-10-08 15:46:41.570053 | controller |
2025-10-08 15:46:41.570145 | controller | TASK [Install some debug utils] ************************************************
2025-10-08 15:46:41.570247 | controller | Wednesday 08 October 2025  15:46:41 +0000 (0:00:00.304)       0:00:01.155 *****
2025-10-08 15:46:45.038455 | controller | changed: [instance]
2025-10-08 15:46:45.038564 | controller |
2025-10-08 15:46:45.038795 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-10-08 15:46:45.057304 | controller | Wednesday 08 October 2025  15:46:45 +0000 (0:00:03.468)       0:00:04.624 *****
2025-10-08 15:46:45.057338 | controller | skipping: [instance]
2025-10-08 15:46:45.099042 | controller |
2025-10-08 15:46:45.099071 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-10-08 15:46:45.099081 | controller | Wednesday 08 October 2025  15:46:45 +0000 (0:00:00.018)       0:00:04.642 *****
2025-10-08 15:46:45.099093 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-10-08 15:46:45.386517 | controller |
2025-10-08 15:46:45.386548 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-10-08 15:46:45.386556 | controller | Wednesday 08 October 2025  15:46:45 +0000 (0:00:00.041)       0:00:04.684 *****
2025-10-08 15:46:45.386566 | controller | ok: [instance]
2025-10-08 15:46:45.605886 | controller |
2025-10-08 15:46:45.605915 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-10-08 15:46:45.605923 | controller | Wednesday 08 October 2025  15:46:45 +0000 (0:00:00.287)       0:00:04.971 *****
2025-10-08 15:46:45.605933 | controller | ok: [instance]
2025-10-08 15:46:46.287458 | controller |
2025-10-08 15:46:46.287491 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-10-08 15:46:46.287499 | controller | Wednesday 08 October 2025  15:46:45 +0000 (0:00:00.219)       0:00:05.191 *****
2025-10-08 15:46:46.287510 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-10-08 15:46:46.345448 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-10-08 15:46:46.345482 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-10-08 15:46:46.345491 | controller |
2025-10-08 15:46:46.345499 | controller | TASK [Deploy repo-setup] *******************************************************
2025-10-08 15:46:46.345506 | controller | Wednesday 08 October 2025  15:46:46 +0000 (0:00:00.681)       0:00:05.872 *****
2025-10-08 15:46:46.345518 | controller |
2025-10-08 15:46:46.345546 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-10-08 15:46:46.345644 | controller | Wednesday 08 October 2025  15:46:46 +0000 (0:00:00.058)       0:00:05.931 *****
2025-10-08 15:46:46.911234 | controller | changed: [instance] => (item=tmp)
2025-10-08 15:46:47.578193 | controller | changed: [instance] => (item=artifacts/repositories)
2025-10-08 15:46:47.578224 | controller | changed: [instance] => (item=venv/repo_setup)
2025-10-08 15:46:47.578233 | controller |
2025-10-08 15:46:47.578245 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-10-08 15:46:47.578254 | controller | Wednesday 08 October 2025  15:46:46 +0000 (0:00:00.565)       0:00:06.496 *****
2025-10-08 15:46:47.578264 | controller | ok: [instance]
2025-10-08 15:46:48.762291 | controller |
2025-10-08 15:46:48.762347 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-10-08 15:46:48.762394 | controller | Wednesday 08 October 2025  15:46:47 +0000 (0:00:00.667)       0:00:07.163 *****
2025-10-08 15:46:48.762409 | controller | changed: [instance]
2025-10-08 15:46:56.815282 | controller |
2025-10-08 15:46:56.815324 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-10-08 15:46:56.815333 | controller | Wednesday 08 October 2025  15:46:48 +0000 (0:00:01.184)       0:00:08.347 *****
2025-10-08 15:46:56.815343 | controller | changed: [instance]
2025-10-08 15:46:57.572751 | controller |
2025-10-08 15:46:57.572786 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-10-08 15:46:57.572794 | controller | Wednesday 08 October 2025  15:46:56 +0000 (0:00:08.053)       0:00:16.400 *****
2025-10-08 15:46:57.572813 | controller | changed: [instance]
2025-10-08 15:46:57.606943 | controller |
2025-10-08 15:46:57.606975 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-10-08 15:46:57.606983 | controller | Wednesday 08 October 2025  15:46:57 +0000 (0:00:00.757)       0:00:17.157 *****
2025-10-08 15:46:57.606993 | controller | skipping: [instance]
2025-10-08 15:46:58.481233 | controller |
2025-10-08 15:46:58.481263 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-10-08 15:46:58.481271 | controller | Wednesday 08 October 2025  15:46:57 +0000 (0:00:00.034)       0:00:17.192 *****
2025-10-08 15:46:58.481282 | controller | changed: [instance]
2025-10-08 15:46:58.519928 | controller |
2025-10-08 15:46:58.519955 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-10-08 15:46:58.519964 | controller | Wednesday 08 October 2025  15:46:58 +0000 (0:00:00.874)       0:00:18.066 *****
2025-10-08 15:46:58.519974 | controller | skipping: [instance]
2025-10-08 15:46:58.558928 | controller |
2025-10-08 15:46:58.558957 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-10-08 15:46:58.558966 | controller | Wednesday 08 October 2025  15:46:58 +0000 (0:00:00.038)       0:00:18.105 *****
2025-10-08 15:46:58.558976 | controller | skipping: [instance]
2025-10-08 15:46:58.598511 | controller |
2025-10-08 15:46:58.598541 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-10-08 15:46:58.598550 | controller | Wednesday 08 October 2025  15:46:58 +0000 (0:00:00.038)       0:00:18.144 *****
2025-10-08 15:46:58.598562 | controller | skipping: [instance]
2025-10-08 15:46:59.180430 | controller |
2025-10-08 15:46:59.180482 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-10-08 15:46:59.180490 | controller | Wednesday 08 October 2025  15:46:58 +0000 (0:00:00.039)       0:00:18.183 *****
2025-10-08 15:46:59.180501 | controller | changed: [instance]
2025-10-08 15:46:59.180892 | controller |
2025-10-08 15:46:59.651889 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-10-08 15:46:59.651921 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.582)       0:00:18.766 *****
2025-10-08 15:46:59.651936 | controller | changed: [instance]
2025-10-08 15:46:59.682029 | controller |
2025-10-08 15:46:59.682062 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-10-08 15:46:59.682071 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.471)       0:00:19.237 *****
2025-10-08 15:46:59.682081 | controller | skipping: [instance]
2025-10-08 15:46:59.711530 | controller |
2025-10-08 15:46:59.711557 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-10-08 15:46:59.711565 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.030)       0:00:19.267 *****
2025-10-08 15:46:59.711575 | controller | skipping: [instance]
2025-10-08 15:46:59.741097 | controller |
2025-10-08 15:46:59.741126 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-10-08 15:46:59.741135 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.029)       0:00:19.297 *****
2025-10-08 15:46:59.741145 | controller | skipping: [instance]
2025-10-08 15:46:59.781919 | controller |
2025-10-08 15:46:59.781953 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-10-08 15:46:59.781963 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.029)       0:00:19.326 *****
2025-10-08 15:46:59.781992 | controller | ok: [instance]
2025-10-08 15:46:59.810969 | controller |
2025-10-08 15:46:59.810996 | controller | TASK [repo_setup : Create download directory] **********************************
2025-10-08 15:46:59.811004 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.040)       0:00:19.367 *****
2025-10-08 15:46:59.811014 | controller | skipping: [instance]
2025-10-08 15:46:59.838686 | controller |
2025-10-08 15:46:59.838715 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-10-08 15:46:59.838723 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.029)       0:00:19.396 *****
2025-10-08 15:46:59.838733 | controller | skipping: [instance]
2025-10-08 15:46:59.866616 | controller |
2025-10-08 15:46:59.866648 | controller | TASK [Download the RPM] ********************************************************
2025-10-08 15:46:59.866657 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.027)       0:00:19.424 *****
2025-10-08 15:46:59.866669 | controller | skipping: [instance]
2025-10-08 15:46:59.866843 | controller |
2025-10-08 15:46:59.867017 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-10-08 15:46:59.867191 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.028)       0:00:19.452 *****
2025-10-08 15:46:59.894741 | controller | skipping: [instance]
2025-10-08 15:46:59.894904 | controller |
2025-10-08 15:46:59.895051 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-10-08 15:46:59.895193 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.028)       0:00:19.480 *****
2025-10-08 15:46:59.926340 | controller | skipping: [instance]
2025-10-08 15:46:59.926534 | controller |
2025-10-08 15:46:59.926687 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-10-08 15:46:59.926832 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.031)       0:00:19.512 *****
2025-10-08 15:46:59.957546 | controller | skipping: [instance]
2025-10-08 15:46:59.957711 | controller |
2025-10-08 15:46:59.957869 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-10-08 15:46:59.958017 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.031)       0:00:19.543 *****
2025-10-08 15:46:59.984462 | controller | skipping: [instance]
2025-10-08 15:46:59.984624 | controller |
2025-10-08 15:46:59.984773 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-10-08 15:46:59.984916 | controller | Wednesday 08 October 2025  15:46:59 +0000 (0:00:00.026)       0:00:19.570 *****
2025-10-08 15:47:00.167650 | controller | ok: [instance]
2025-10-08 15:47:00.390423 | controller |
2025-10-08 15:47:00.390455 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-10-08 15:47:00.390463 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.182)       0:00:19.752 *****
2025-10-08 15:47:00.390473 | controller | changed: [instance]
2025-10-08 15:47:00.390570 | controller |
2025-10-08 15:47:00.390580 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-10-08 15:47:00.390588 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.222)       0:00:19.975 *****
2025-10-08 15:47:00.630339 | controller | changed: [instance]
2025-10-08 15:47:00.654010 | controller |
2025-10-08 15:47:00.654042 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-10-08 15:47:00.654050 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.239)       0:00:20.215 *****
2025-10-08 15:47:00.654060 | controller | skipping: [instance]
2025-10-08 15:47:00.679619 | controller |
2025-10-08 15:47:00.679649 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-10-08 15:47:00.679658 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.023)       0:00:20.239 *****
2025-10-08 15:47:00.679673 | controller | skipping: [instance]
2025-10-08 15:47:00.705053 | controller |
2025-10-08 15:47:00.705082 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-10-08 15:47:00.705091 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.025)       0:00:20.265 *****
2025-10-08 15:47:00.705100 | controller | skipping: [instance]
2025-10-08 15:47:00.728448 | controller |
2025-10-08 15:47:00.728480 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-10-08 15:47:00.728496 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.025)       0:00:20.290 *****
2025-10-08 15:47:00.728507 | controller | skipping: [instance]
2025-10-08 15:47:00.728595 | controller |
2025-10-08 15:47:00.728625 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-10-08 15:47:00.728638 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.023)       0:00:20.313 *****
2025-10-08 15:47:00.752884 | controller | skipping: [instance]
2025-10-08 15:47:00.776553 | controller |
2025-10-08 15:47:00.776578 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-10-08 15:47:00.776586 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.024)       0:00:20.338 *****
2025-10-08 15:47:00.776595 | controller | skipping: [instance]
2025-10-08 15:47:00.795736 | controller |
2025-10-08 15:47:00.795771 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-10-08 15:47:00.795780 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.023)       0:00:20.361 *****
2025-10-08 15:47:00.795790 | controller | skipping: [instance]
2025-10-08 15:47:00.825767 | controller |
2025-10-08 15:47:00.825804 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-10-08 15:47:00.825812 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.018)       0:00:20.380 *****
2025-10-08 15:47:00.825823 | controller | skipping: [instance]
2025-10-08 15:47:00.826022 | controller |
2025-10-08 15:47:00.826191 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-10-08 15:47:00.826388 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.030)       0:00:20.411 *****
2025-10-08 15:47:00.844295 | controller | skipping: [instance]
2025-10-08 15:47:00.844521 | controller |
2025-10-08 15:47:00.844694 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-10-08 15:47:00.844856 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.018)       0:00:20.430 *****
2025-10-08 15:47:00.870023 | controller | skipping: [instance]
2025-10-08 15:47:00.870215 | controller |
2025-10-08 15:47:00.870418 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-10-08 15:47:00.870576 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.025)       0:00:20.455 *****
2025-10-08 15:47:00.900467 | controller | skipping: [instance]
2025-10-08 15:47:00.900627 | controller |
2025-10-08 15:47:00.900774 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-10-08 15:47:00.900917 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.030)       0:00:20.486 *****
2025-10-08 15:47:00.930974 | controller | skipping: [instance]
2025-10-08 15:47:00.931141 | controller |
2025-10-08 15:47:00.931308 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-10-08 15:47:00.931483 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.030)       0:00:20.516 *****
2025-10-08 15:47:00.962148 | controller | skipping: [instance]
2025-10-08 15:47:00.962320 | controller |
2025-10-08 15:47:00.962492 | controller | TASK [test_deps : Install additional packages] *********************************
2025-10-08 15:47:00.962642 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.031)       0:00:20.547 *****
2025-10-08 15:47:00.993221 | controller | skipping: [instance]
2025-10-08 15:47:00.993419 | controller |
2025-10-08 15:47:00.993576 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-10-08 15:47:00.993719 | controller | Wednesday 08 October 2025  15:47:00 +0000 (0:00:00.031)       0:00:20.579 *****
2025-10-08 15:47:47.218020 | controller | ok: [instance]
2025-10-08 15:47:48.388730 | controller |
2025-10-08 15:47:48.388773 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-10-08 15:47:48.388782 | controller | Wednesday 08 October 2025  15:47:47 +0000 (0:00:46.224)       0:01:06.803 *****
2025-10-08 15:47:48.388792 | controller | ok: [instance]
2025-10-08 15:47:48.425563 | controller |
2025-10-08 15:47:48.425589 | controller | TASK [test_deps : Install extra packages] **************************************
2025-10-08 15:47:48.425598 | controller | Wednesday 08 October 2025  15:47:48 +0000 (0:00:01.170)       0:01:07.973 *****
2025-10-08 15:47:48.425610 | controller | skipping: [instance]
2025-10-08 15:47:48.644112 | controller |
2025-10-08 15:47:48.644142 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-10-08 15:47:48.644150 | controller | Wednesday 08 October 2025  15:47:48 +0000 (0:00:00.036)       0:01:08.010 *****
2025-10-08 15:47:48.644159 | controller | ok: [instance]
2025-10-08 15:47:48.842444 | controller |
2025-10-08 15:47:48.842474 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-10-08 15:47:48.842487 | controller | Wednesday 08 October 2025  15:47:48 +0000 (0:00:00.218)       0:01:08.229 *****
2025-10-08 15:47:48.842498 | controller | changed: [instance]
2025-10-08 15:47:49.040811 | controller |
2025-10-08 15:47:49.040841 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-10-08 15:47:49.040849 | controller | Wednesday 08 October 2025  15:47:48 +0000 (0:00:00.198)       0:01:08.427 *****
2025-10-08 15:47:49.040859 | controller | ok: [instance]
2025-10-08 15:47:49.069404 | controller |
2025-10-08 15:47:49.069429 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-10-08 15:47:49.069437 | controller | Wednesday 08 October 2025  15:47:49 +0000 (0:00:00.198)       0:01:08.626 *****
2025-10-08 15:47:49.069446 | controller | skipping: [instance]
2025-10-08 15:47:49.086463 | controller |
2025-10-08 15:47:49.086499 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-10-08 15:47:49.086508 | controller | Wednesday 08 October 2025  15:47:49 +0000 (0:00:00.028)       0:01:08.654 *****
2025-10-08 15:47:49.086518 | controller | skipping: [instance]
2025-10-08 15:47:49.086559 | controller |
2025-10-08 15:47:49.086580 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-10-08 15:47:49.086591 | controller | Wednesday 08 October 2025  15:47:49 +0000 (0:00:00.017)       0:01:08.672 *****
2025-10-08 15:47:49.106084 | controller | ok: [instance]
2025-10-08 15:47:49.133120 | controller |
2025-10-08 15:47:49.133144 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-10-08 15:47:49.133151 | controller | Wednesday 08 October 2025  15:47:49 +0000 (0:00:00.019)       0:01:08.691 *****
2025-10-08 15:47:49.133160 | controller | skipping: [instance]
2025-10-08 15:49:01.655183 | controller |
2025-10-08 15:49:01.655229 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-10-08 15:49:01.655238 | controller | Wednesday 08 October 2025  15:47:49 +0000 (0:00:00.027)       0:01:08.718 *****
2025-10-08 15:49:01.655249 | controller | changed: [instance]
2025-10-08 15:49:01.655268 | controller |
2025-10-08 15:49:01.655433 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-10-08 15:49:01.655618 | controller | Wednesday 08 October 2025  15:49:01 +0000 (0:01:12.522)       0:02:21.240 *****
2025-10-08 15:49:01.874067 | controller | changed: [instance]
2025-10-08 15:49:01.874331 | controller |
2025-10-08 15:49:02.276809 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-10-08 15:49:02.276841 | controller | Wednesday 08 October 2025  15:49:01 +0000 (0:00:00.218)       0:02:21.459 *****
2025-10-08 15:49:02.276854 | controller | changed: [instance]
2025-10-08 15:49:02.880155 | controller |
2025-10-08 15:49:02.880186 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-10-08 15:49:02.880194 | controller | Wednesday 08 October 2025  15:49:02 +0000 (0:00:00.402)       0:02:21.862 *****
2025-10-08 15:49:02.880205 | controller | changed: [instance]
2025-10-08 15:49:02.880453 | controller |
2025-10-08 15:49:03.088837 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-10-08 15:49:03.088869 | controller | Wednesday 08 October 2025  15:49:02 +0000 (0:00:00.603)       0:02:22.465 *****
2025-10-08 15:49:03.088882 | controller | ok: [instance]
2025-10-08 15:49:03.089165 | controller |
2025-10-08 15:49:03.797799 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-10-08 15:49:03.797833 | controller | Wednesday 08 October 2025  15:49:03 +0000 (0:00:00.208)       0:02:22.674 *****
2025-10-08 15:49:03.797846 | controller | ok: [instance]
2025-10-08 15:49:04.677439 | controller |
2025-10-08 15:49:04.677480 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-10-08 15:49:04.677489 | controller | Wednesday 08 October 2025  15:49:03 +0000 (0:00:00.708)       0:02:23.383 *****
2025-10-08 15:49:04.677510 | controller | changed: [instance]
2025-10-08 15:49:04.677540 | controller |
2025-10-08 15:49:04.677564 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-10-08 15:49:04.677734 | controller | Wednesday 08 October 2025  15:49:04 +0000 (0:00:00.879)       0:02:24.262 *****
2025-10-08 15:49:04.756407 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-10-08 15:49:04.756943 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-10-08 15:49:04.756973 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-10-08 15:49:04.756981 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-10-08 15:49:04.756986 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-10-08 15:49:04.756992 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-10-08 15:49:04.757002 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-10-08 15:49:05.127455 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-10-08 15:49:05.127490 | controller |
2025-10-08 15:49:05.127498 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-10-08 15:49:05.127505 | controller | Wednesday 08 October 2025  15:49:04 +0000 (0:00:00.078)       0:02:24.341 *****
2025-10-08 15:49:05.127515 | controller | changed: [instance]
2025-10-08 15:49:05.127540 | controller |
2025-10-08 15:49:05.127546 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-10-08 15:49:05.127554 | controller | Wednesday 08 October 2025  15:49:05 +0000 (0:00:00.371)       0:02:24.712 *****
2025-10-08 15:49:05.465748 | controller | changed: [instance]
2025-10-08 15:49:05.465789 | controller |
2025-10-08 15:49:05.465797 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-10-08 15:49:05.465807 | controller | Wednesday 08 October 2025  15:49:05 +0000 (0:00:00.338)       0:02:25.051 *****
2025-10-08 15:49:05.807000 | controller | changed: [instance]
2025-10-08 15:49:06.144385 | controller |
2025-10-08 15:49:06.144419 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-10-08 15:49:06.144427 | controller | Wednesday 08 October 2025  15:49:05 +0000 (0:00:00.341)       0:02:25.392 *****
2025-10-08 15:49:06.144438 | controller | changed: [instance]
2025-10-08 15:49:06.144498 | controller |
2025-10-08 15:49:06.144508 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-10-08 15:49:06.144516 | controller | Wednesday 08 October 2025  15:49:06 +0000 (0:00:00.337)       0:02:25.729 *****
2025-10-08 15:49:06.483833 | controller | changed: [instance]
2025-10-08 15:49:06.852458 | controller |
2025-10-08 15:49:06.852491 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-10-08 15:49:06.852501 | controller | Wednesday 08 October 2025  15:49:06 +0000 (0:00:00.339)       0:02:26.069 *****
2025-10-08 15:49:06.852514 | controller | changed: [instance]
2025-10-08 15:49:07.202913 | controller |
2025-10-08 15:49:07.202946 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-10-08 15:49:07.202955 | controller | Wednesday 08 October 2025  15:49:06 +0000 (0:00:00.368)       0:02:26.437 *****
2025-10-08 15:49:07.202965 | controller | changed: [instance]
2025-10-08 15:49:07.534158 | controller |
2025-10-08 15:49:07.534190 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-10-08 15:49:07.534199 | controller | Wednesday 08 October 2025  15:49:07 +0000 (0:00:00.350)       0:02:26.788 *****
2025-10-08 15:49:07.534209 | controller | changed: [instance]
2025-10-08 15:49:07.883112 | controller |
2025-10-08 15:49:07.883149 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-10-08 15:49:07.883158 | controller | Wednesday 08 October 2025  15:49:07 +0000 (0:00:00.331)       0:02:27.119 *****
2025-10-08 15:49:07.883169 | controller | changed: [instance]
2025-10-08 15:49:08.219785 | controller |
2025-10-08 15:49:08.219817 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-10-08 15:49:08.219826 | controller | Wednesday 08 October 2025  15:49:07 +0000 (0:00:00.348)       0:02:27.468 *****
2025-10-08 15:49:08.219836 | controller | changed: [instance]
2025-10-08 15:49:08.553077 | controller |
2025-10-08 15:49:08.553110 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-10-08 15:49:08.553118 | controller | Wednesday 08 October 2025  15:49:08 +0000 (0:00:00.336)       0:02:27.805 *****
2025-10-08 15:49:08.553128 | controller | changed: [instance]
2025-10-08 15:49:08.894817 | controller |
2025-10-08 15:49:08.894847 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-10-08 15:49:08.894855 | controller | Wednesday 08 October 2025  15:49:08 +0000 (0:00:00.333)       0:02:28.138 *****
2025-10-08 15:49:08.894865 | controller | changed: [instance]
2025-10-08 15:49:09.239407 | controller |
2025-10-08 15:49:09.239437 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-10-08 15:49:09.239446 | controller | Wednesday 08 October 2025  15:49:08 +0000 (0:00:00.341)       0:02:28.480 *****
2025-10-08 15:49:09.239456 | controller | changed: [instance]
2025-10-08 15:49:09.579266 | controller |
2025-10-08 15:49:09.579298 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-10-08 15:49:09.579307 | controller | Wednesday 08 October 2025  15:49:09 +0000 (0:00:00.344)       0:02:28.824 *****
2025-10-08 15:49:09.579317 | controller | changed: [instance]
2025-10-08 15:49:09.910513 | controller |
2025-10-08 15:49:09.910548 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-10-08 15:49:09.910556 | controller | Wednesday 08 October 2025  15:49:09 +0000 (0:00:00.339)       0:02:29.164 *****
2025-10-08 15:49:09.910567 | controller | changed: [instance]
2025-10-08 15:49:09.911004 | controller |
2025-10-08 15:49:10.247279 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-10-08 15:49:10.247312 | controller | Wednesday 08 October 2025  15:49:09 +0000 (0:00:00.331)       0:02:29.496 *****
2025-10-08 15:49:10.247324 | controller | changed: [instance]
2025-10-08 15:49:10.602841 | controller |
2025-10-08 15:49:10.602871 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-10-08 15:49:10.602879 | controller | Wednesday 08 October 2025  15:49:10 +0000 (0:00:00.336)       0:02:29.832 *****
2025-10-08 15:49:10.602890 | controller | changed: [instance]
2025-10-08 15:49:10.935970 | controller |
2025-10-08 15:49:10.936001 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-10-08 15:49:10.936016 | controller | Wednesday 08 October 2025  15:49:10 +0000 (0:00:00.355)       0:02:30.188 *****
2025-10-08 15:49:10.936026 | controller | changed: [instance]
2025-10-08 15:49:11.271385 | controller |
2025-10-08 15:49:11.271418 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-10-08 15:49:11.271427 | controller | Wednesday 08 October 2025  15:49:10 +0000 (0:00:00.333)       0:02:30.521 *****
2025-10-08 15:49:11.271437 | controller | changed: [instance]
2025-10-08 15:49:11.615405 | controller |
2025-10-08 15:49:11.615437 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-10-08 15:49:11.615445 | controller | Wednesday 08 October 2025  15:49:11 +0000 (0:00:00.335)       0:02:30.856 *****
2025-10-08 15:49:11.615455 | controller | changed: [instance]
2025-10-08 15:49:11.961438 | controller |
2025-10-08 15:49:11.961524 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-10-08 15:49:11.961534 | controller | Wednesday 08 October 2025  15:49:11 +0000 (0:00:00.344)       0:02:31.200 *****
2025-10-08 15:49:11.961546 | controller | changed: [instance]
2025-10-08 15:49:11.961582 | controller |
2025-10-08 15:49:11.961787 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-10-08 15:49:12.315550 | controller | Wednesday 08 October 2025  15:49:11 +0000 (0:00:00.346)       0:02:31.547 *****
2025-10-08 15:49:12.315593 | controller | changed: [instance]
2025-10-08 15:49:12.678575 | controller |
2025-10-08 15:49:12.678607 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-10-08 15:49:12.678615 | controller | Wednesday 08 October 2025  15:49:12 +0000 (0:00:00.353)       0:02:31.900 *****
2025-10-08 15:49:12.678625 | controller | changed: [instance]
2025-10-08 15:49:13.024556 | controller |
2025-10-08 15:49:13.024588 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-10-08 15:49:13.024596 | controller | Wednesday 08 October 2025  15:49:12 +0000 (0:00:00.363)       0:02:32.263 *****
2025-10-08 15:49:13.024606 | controller | changed: [instance]
2025-10-08 15:49:13.044479 | controller |
2025-10-08 15:49:13.044514 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-10-08 15:49:13.044522 | controller | Wednesday 08 October 2025  15:49:13 +0000 (0:00:00.345)       0:02:32.609 *****
2025-10-08 15:49:13.044533 | controller | skipping: [instance]
2025-10-08 15:49:13.044729 | controller |
2025-10-08 15:49:13.044776 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-10-08 15:49:13.332977 | controller | Wednesday 08 October 2025  15:49:13 +0000 (0:00:00.020)       0:02:32.630 *****
2025-10-08 15:49:13.333010 | controller | ok: [instance]
2025-10-08 15:49:13.744924 | controller |
2025-10-08 15:49:13.744956 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-10-08 15:49:13.744964 | controller | Wednesday 08 October 2025  15:49:13 +0000 (0:00:00.288)       0:02:32.918 *****
2025-10-08 15:49:13.744974 | controller | changed: [instance]
2025-10-08 15:49:14.068583 | controller |
2025-10-08 15:49:14.068615 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-10-08 15:49:14.068623 | controller | Wednesday 08 October 2025  15:49:13 +0000 (0:00:00.411)       0:02:33.330 *****
2025-10-08 15:49:14.068633 | controller | changed: [instance]
2025-10-08 15:49:14.365264 | controller |
2025-10-08 15:49:14.365294 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-10-08 15:49:14.365302 | controller | Wednesday 08 October 2025  15:49:14 +0000 (0:00:00.323)       0:02:33.653 *****
2025-10-08 15:49:14.365313 | controller | [WARNING]: Reset is not implemented for this connection
2025-10-08 15:49:14.386445 | controller | changed: [instance]
2025-10-08 15:49:14.386484 | controller |
2025-10-08 15:49:14.386492 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-10-08 15:49:14.386499 | controller | Wednesday 08 October 2025  15:49:14 +0000 (0:00:00.292)       0:02:33.945 *****
2025-10-08 15:49:14.386507 | controller |
2025-10-08 15:49:14.387418 | controller | PLAY RECAP *********************************************************************
2025-10-08 15:49:14.389106 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-10-08 15:49:14.389123 | controller |
2025-10-08 15:49:14.389130 | controller | Wednesday 08 October 2025  15:49:14 +0000 (0:00:00.025)       0:02:33.971 *****
2025-10-08 15:49:14.389136 | controller | ===============================================================================
2025-10-08 15:49:14.389141 | controller | libvirt_manager : Install packages required for using KVM -------------- 72.52s
2025-10-08 15:49:14.389147 | controller | test_deps : Install selinux python libs -------------------------------- 46.22s
2025-10-08 15:49:14.389152 | controller | repo_setup : Initialize python venv and install requirements ------------ 8.05s
2025-10-08 15:49:14.389165 | controller | Install some debug utils ------------------------------------------------ 3.47s
2025-10-08 15:49:14.448786 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.18s
2025-10-08 15:49:14.448819 | controller | test_deps : Install python yaml libs ------------------------------------ 1.17s
2025-10-08 15:49:14.448827 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.88s
2025-10-08 15:49:14.448832 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.87s
2025-10-08 15:49:14.448838 | controller | Gathering Facts --------------------------------------------------------- 0.83s
2025-10-08 15:49:14.448843 | controller | repo_setup : Install repo-setup package --------------------------------- 0.76s
2025-10-08 15:49:14.448848 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.71s
2025-10-08 15:49:14.448859 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.68s
2025-10-08 15:49:14.448865 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.67s
2025-10-08 15:49:14.448870 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.60s
2025-10-08 15:49:14.448876 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.58s
2025-10-08 15:49:14.448881 | controller | repo_setup : Ensure directories are present ----------------------------- 0.57s
2025-10-08 15:49:14.448886 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.47s
2025-10-08 15:49:14.448892 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.41s
2025-10-08 15:49:14.448897 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.40s
2025-10-08 15:49:14.448902 | controller | libvirt_manager : Ensure read-write socket is enabled for qemu. --------- 0.37s
2025-10-08 15:49:14.448912 | controller | INFO     Running default > converge
2025-10-08 15:49:14.888140 | controller |
2025-10-08 15:49:15.689381 | controller | PLAY [Converge] ****************************************************************
2025-10-08 15:49:15.689414 | controller |
2025-10-08 15:49:15.689422 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 15:49:15.689428 | controller | Wednesday 08 October 2025  15:49:14 +0000 (0:00:00.013)       0:00:00.013 *****
2025-10-08 15:49:15.689438 | controller | ok: [instance]
2025-10-08 15:49:16.084435 | controller |
2025-10-08 15:49:16.084470 | controller | TASK [Crate SSH keypair] *******************************************************
2025-10-08 15:49:16.084478 | controller | Wednesday 08 October 2025  15:49:15 +0000 (0:00:00.801)       0:00:00.815 *****
2025-10-08 15:49:16.084488 | controller | changed: [instance]
2025-10-08 15:49:16.084704 | controller |
2025-10-08 15:49:16.084718 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-10-08 15:49:16.584805 | controller | Wednesday 08 October 2025  15:49:16 +0000 (0:00:00.395)       0:00:01.210 *****
2025-10-08 15:49:16.584842 | controller | changed: [instance]
2025-10-08 15:49:17.591599 | controller |
2025-10-08 15:49:17.591632 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-08 15:49:17.591640 | controller | Wednesday 08 October 2025  15:49:16 +0000 (0:00:00.500)       0:00:01.710 *****
2025-10-08 15:49:17.591650 | controller | changed: [instance]
2025-10-08 15:49:17.628460 | controller |
2025-10-08 15:49:17.628494 | controller | TASK [Discover latest image] ***************************************************
2025-10-08 15:49:17.628504 | controller | Wednesday 08 October 2025  15:49:17 +0000 (0:00:01.006)       0:00:02.717 *****
2025-10-08 15:49:17.628516 | controller |
2025-10-08 15:49:17.628548 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-10-08 15:49:17.628679 | controller | Wednesday 08 October 2025  15:49:17 +0000 (0:00:00.036)       0:00:02.754 *****
2025-10-08 15:49:19.356796 | controller | changed: [instance]
2025-10-08 15:49:19.382989 | controller |
2025-10-08 15:49:19.383020 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-10-08 15:49:19.383033 | controller | Wednesday 08 October 2025  15:49:19 +0000 (0:00:01.728)       0:00:04.482 *****
2025-10-08 15:49:19.383044 | controller | ok: [instance]
2025-10-08 15:49:39.983269 | controller |
2025-10-08 15:49:39.983325 | controller | TASK [Download latest image] ***************************************************
2025-10-08 15:49:39.983334 | controller | Wednesday 08 October 2025  15:49:19 +0000 (0:00:00.026)       0:00:04.509 *****
2025-10-08 15:49:39.983346 | controller | changed: [instance]
2025-10-08 15:49:40.019492 | controller |
2025-10-08 15:49:40.019557 | controller | TASK [Build nat64 appliance image] *********************************************
2025-10-08 15:49:40.019567 | controller | Wednesday 08 October 2025  15:49:39 +0000 (0:00:20.599)       0:00:25.108 *****
2025-10-08 15:49:40.019579 | controller |
2025-10-08 15:49:40.019776 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-10-08 15:49:40.513586 | controller | Wednesday 08 October 2025  15:49:40 +0000 (0:00:00.037)       0:00:25.145 *****
2025-10-08 15:49:40.513633 | controller | ok: [instance] => (item=artifacts)
2025-10-08 15:49:40.712526 | controller | ok: [instance] => (item=logs)
2025-10-08 15:49:40.712567 | controller |
2025-10-08 15:49:40.712575 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-10-08 15:49:40.712582 | controller | Wednesday 08 October 2025  15:49:40 +0000 (0:00:00.494)       0:00:25.639 *****
2025-10-08 15:49:40.712592 | controller | changed: [instance]
2025-10-08 15:49:45.314196 | controller |
2025-10-08 15:49:45.314229 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-10-08 15:49:45.314237 | controller | Wednesday 08 October 2025  15:49:40 +0000 (0:00:00.199)       0:00:25.838 *****
2025-10-08 15:49:45.314247 | controller | ok: [instance]
2025-10-08 15:49:53.572220 | controller |
2025-10-08 15:49:53.572253 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-10-08 15:49:53.572261 | controller | Wednesday 08 October 2025  15:49:45 +0000 (0:00:04.601)       0:00:30.440 *****
2025-10-08 15:49:53.572271 | controller | changed: [instance]
2025-10-08 15:50:03.707045 | controller |
2025-10-08 15:50:03.707077 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-10-08 15:50:03.707086 | controller | Wednesday 08 October 2025  15:49:53 +0000 (0:00:08.258)       0:00:38.698 *****
2025-10-08 15:50:03.707097 | controller | changed: [instance] => (item=elements/)
2025-10-08 15:50:04.937924 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-10-08 15:50:04.937959 | controller |
2025-10-08 15:50:04.937967 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-10-08 15:50:04.937974 | controller | Wednesday 08 October 2025  15:50:03 +0000 (0:00:10.133)       0:00:48.832 *****
2025-10-08 15:50:04.937984 | controller | changed: [instance]
2025-10-08 15:54:15.254484 | controller |
2025-10-08 15:54:15.254642 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-10-08 15:54:15.254654 | controller | Wednesday 08 October 2025  15:50:04 +0000 (0:00:01.231)       0:00:50.063 *****
2025-10-08 15:54:15.254666 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-08 15:54:15.467345 | controller | changed: [instance]
2025-10-08 15:54:15.467388 | controller |
2025-10-08 15:54:15.467400 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-10-08 15:54:15.467407 | controller | Wednesday 08 October 2025  15:54:15 +0000 (0:04:10.316)       0:05:00.380 *****
2025-10-08 15:54:15.467417 | controller | changed: [instance]
2025-10-08 15:54:22.872045 | controller |
2025-10-08 15:54:22.872080 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-10-08 15:54:22.872088 | controller | Wednesday 08 October 2025  15:54:15 +0000 (0:00:00.213)       0:05:00.593 *****
2025-10-08 15:54:22.872098 | controller | changed: [instance]
2025-10-08 15:54:22.918492 | controller |
2025-10-08 15:54:22.918523 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-10-08 15:54:22.918533 | controller | Wednesday 08 October 2025  15:54:22 +0000 (0:00:07.404)       0:05:07.998 *****
2025-10-08 15:54:22.918545 | controller |
2025-10-08 15:54:22.918569 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-10-08 15:54:22.918609 | controller | Wednesday 08 October 2025  15:54:22 +0000 (0:00:00.046)       0:05:08.045 *****
2025-10-08 15:54:23.005263 | controller | ok: [instance]
2025-10-08 15:54:23.781615 | controller |
2025-10-08 15:54:23.781644 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-10-08 15:54:23.781653 | controller | Wednesday 08 October 2025  15:54:23 +0000 (0:00:00.086)       0:05:08.131 *****
2025-10-08 15:54:23.781663 | controller | changed: [instance]
2025-10-08 15:54:24.103057 | controller |
2025-10-08 15:54:24.103092 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-10-08 15:54:24.103100 | controller | Wednesday 08 October 2025  15:54:23 +0000 (0:00:00.776)       0:05:08.907 *****
2025-10-08 15:54:24.103116 | controller | ok: [instance]
2025-10-08 15:54:24.330490 | controller |
2025-10-08 15:54:24.330521 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-10-08 15:54:24.330529 | controller | Wednesday 08 October 2025  15:54:24 +0000 (0:00:00.321)       0:05:09.229 *****
2025-10-08 15:54:24.330547 | controller | ok: [instance]
2025-10-08 15:54:24.563865 | controller |
2025-10-08 15:54:24.563896 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-10-08 15:54:24.563904 | controller | Wednesday 08 October 2025  15:54:24 +0000 (0:00:00.227)       0:05:09.456 *****
2025-10-08 15:54:24.563915 | controller | changed: [instance]
2025-10-08 15:54:24.794803 | controller |
2025-10-08 15:54:24.794834 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-10-08 15:54:24.794842 | controller | Wednesday 08 October 2025  15:54:24 +0000 (0:00:00.233)       0:05:09.689 *****
2025-10-08 15:54:24.794852 | controller | changed: [instance]
2025-10-08 15:54:25.034489 | controller |
2025-10-08 15:54:25.034519 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-10-08 15:54:25.034527 | controller | Wednesday 08 October 2025  15:54:24 +0000 (0:00:00.230)       0:05:09.920 *****
2025-10-08 15:54:25.034538 | controller | ok: [instance]
2025-10-08 15:54:25.034562 | controller |
2025-10-08 15:54:25.034780 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-10-08 15:54:25.264448 | controller | Wednesday 08 October 2025  15:54:25 +0000 (0:00:00.239)       0:05:10.160 *****
2025-10-08 15:54:25.264486 | controller | ok: [instance]
2025-10-08 15:54:25.264515 | controller |
2025-10-08 15:54:25.264727 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-10-08 15:54:25.489596 | controller | Wednesday 08 October 2025  15:54:25 +0000 (0:00:00.229)       0:05:10.390 *****
2025-10-08 15:54:25.489633 | controller | changed: [instance]
2025-10-08 15:54:26.262439 | controller |
2025-10-08 15:54:26.262493 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-10-08 15:54:26.262502 | controller | Wednesday 08 October 2025  15:54:25 +0000 (0:00:00.224)       0:05:10.615 *****
2025-10-08 15:54:26.262515 | controller | changed: [instance] => (item=br-64v6)
2025-10-08 15:54:26.262712 | controller | changed: [instance] => (item=br-64v4)
2025-10-08 15:54:26.262742 | controller |
2025-10-08 15:54:26.262755 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-10-08 15:54:27.141441 | controller | Wednesday 08 October 2025  15:54:26 +0000 (0:00:00.773)       0:05:11.388 *****
2025-10-08 15:54:27.141479 | controller | changed: [instance]
2025-10-08 15:54:27.141504 | controller |
2025-10-08 15:54:27.141513 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-10-08 15:54:27.141662 | controller | Wednesday 08 October 2025  15:54:27 +0000 (0:00:00.879)       0:05:12.267 *****
2025-10-08 15:54:27.173783 | controller | ok: [instance]
2025-10-08 15:54:27.209644 | controller |
2025-10-08 15:54:27.209674 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-10-08 15:54:27.209682 | controller | Wednesday 08 October 2025  15:54:27 +0000 (0:00:00.032)       0:05:12.299 *****
2025-10-08 15:54:27.209692 | controller |
2025-10-08 15:54:27.608223 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-08 15:54:27.608254 | controller | Wednesday 08 October 2025  15:54:27 +0000 (0:00:00.035)       0:05:12.335 *****
2025-10-08 15:54:27.608266 | controller | ok: [instance] => (item=artifacts)
2025-10-08 15:54:28.924904 | controller | ok: [instance] => (item=logs)
2025-10-08 15:54:28.924935 | controller |
2025-10-08 15:54:28.924944 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-08 15:54:28.924950 | controller | Wednesday 08 October 2025  15:54:27 +0000 (0:00:00.398)       0:05:12.734 *****
2025-10-08 15:54:28.924960 | controller | ok: [instance]
2025-10-08 15:54:29.134047 | controller |
2025-10-08 15:54:29.134078 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-08 15:54:29.134087 | controller | Wednesday 08 October 2025  15:54:28 +0000 (0:00:01.316)       0:05:14.050 *****
2025-10-08 15:54:29.134097 | controller | changed: [instance]
2025-10-08 15:54:29.496443 | controller |
2025-10-08 15:54:29.496475 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-08 15:54:29.496483 | controller | Wednesday 08 October 2025  15:54:29 +0000 (0:00:00.209)       0:05:14.260 *****
2025-10-08 15:54:29.496494 | controller | changed: [instance]
2025-10-08 15:54:29.496688 | controller |
2025-10-08 15:54:29.496723 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-08 15:54:29.892154 | controller | Wednesday 08 October 2025  15:54:29 +0000 (0:00:00.362)       0:05:14.622 *****
2025-10-08 15:54:29.892191 | controller | changed: [instance]
2025-10-08 15:54:30.267436 | controller |
2025-10-08 15:54:30.267468 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-08 15:54:30.267482 | controller | Wednesday 08 October 2025  15:54:29 +0000 (0:00:00.395)       0:05:15.018 *****
2025-10-08 15:54:30.267492 | controller | changed: [instance]
2025-10-08 15:54:30.463976 | controller |
2025-10-08 15:54:30.464006 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-08 15:54:30.464015 | controller | Wednesday 08 October 2025  15:54:30 +0000 (0:00:00.375)       0:05:15.393 *****
2025-10-08 15:54:30.464024 | controller | ok: [instance]
2025-10-08 15:54:30.480834 | controller |
2025-10-08 15:54:30.480864 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-08 15:54:30.480873 | controller | Wednesday 08 October 2025  15:54:30 +0000 (0:00:00.196)       0:05:15.589 *****
2025-10-08 15:54:30.480885 | controller | skipping: [instance]
2025-10-08 15:54:30.715416 | controller |
2025-10-08 15:54:30.715450 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-08 15:54:30.715459 | controller | Wednesday 08 October 2025  15:54:30 +0000 (0:00:00.017)       0:05:15.607 *****
2025-10-08 15:54:30.715470 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-08 15:54:31.844861 | controller | changed: [instance]
2025-10-08 15:54:31.844893 | controller |
2025-10-08 15:54:31.844901 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-10-08 15:54:31.844908 | controller | Wednesday 08 October 2025  15:54:30 +0000 (0:00:00.234)       0:05:15.841 *****
2025-10-08 15:54:31.844918 | controller | changed: [instance]
2025-10-08 15:54:32.681637 | controller |
2025-10-08 15:54:32.681678 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-10-08 15:54:32.681687 | controller | Wednesday 08 October 2025  15:54:31 +0000 (0:00:01.129)       0:05:16.971 *****
2025-10-08 15:54:32.681697 | controller | changed: [instance]
2025-10-08 15:54:32.705927 | controller |
2025-10-08 15:54:32.705952 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-10-08 15:54:32.705961 | controller | Wednesday 08 October 2025  15:54:32 +0000 (0:00:00.836)       0:05:17.807 *****
2025-10-08 15:54:32.705971 | controller | ok: [instance]
2025-10-08 15:54:32.746118 | controller |
2025-10-08 15:54:32.746152 | controller | TASK [Set MAC address facts] ***************************************************
2025-10-08 15:54:32.746160 | controller | Wednesday 08 October 2025  15:54:32 +0000 (0:00:00.024)       0:05:17.832 *****
2025-10-08 15:54:32.746171 | controller | ok: [instance]
2025-10-08 15:54:33.008195 | controller |
2025-10-08 15:54:33.008228 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-10-08 15:54:33.008236 | controller | Wednesday 08 October 2025  15:54:32 +0000 (0:00:00.039)       0:05:17.871 *****
2025-10-08 15:54:33.008246 | controller | changed: [instance]
2025-10-08 15:54:33.308082 | controller |
2025-10-08 15:54:33.308114 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-10-08 15:54:33.308122 | controller | Wednesday 08 October 2025  15:54:33 +0000 (0:00:00.258)       0:05:18.130 *****
2025-10-08 15:54:33.308133 | controller | ok: [instance]
2025-10-08 15:54:33.537092 | controller |
2025-10-08 15:54:33.537127 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-10-08 15:54:33.537136 | controller | Wednesday 08 October 2025  15:54:33 +0000 (0:00:00.300)       0:05:18.431 *****
2025-10-08 15:54:33.537146 | controller | ok: [instance]
2025-10-08 15:54:33.757645 | controller |
2025-10-08 15:54:33.757676 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-10-08 15:54:33.757684 | controller | Wednesday 08 October 2025  15:54:33 +0000 (0:00:00.231)       0:05:18.663 *****
2025-10-08 15:54:33.757694 | controller | changed: [instance]
2025-10-08 15:54:34.103663 | controller |
2025-10-08 15:54:34.103695 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-10-08 15:54:34.103712 | controller | Wednesday 08 October 2025  15:54:33 +0000 (0:00:00.220)       0:05:18.883 *****
2025-10-08 15:54:34.103723 | controller | changed: [instance]
2025-10-08 15:54:34.922942 | controller |
2025-10-08 15:54:34.922972 | controller | TASK [Restart firewalld.service] ***********************************************
2025-10-08 15:54:34.922980 | controller | Wednesday 08 October 2025  15:54:34 +0000 (0:00:00.346)       0:05:19.229 *****
2025-10-08 15:54:34.922990 | controller | changed: [instance]
2025-10-08 15:54:34.955181 | controller |
2025-10-08 15:54:34.955211 | controller | TASK [Generate test node UUID] *************************************************
2025-10-08 15:54:34.955219 | controller | Wednesday 08 October 2025  15:54:34 +0000 (0:00:00.819)       0:05:20.049 *****
2025-10-08 15:54:34.955229 | controller | ok: [instance]
2025-10-08 15:54:43.215620 | controller |
2025-10-08 15:54:43.215652 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-10-08 15:54:43.215661 | controller | Wednesday 08 October 2025  15:54:34 +0000 (0:00:00.031)       0:05:20.080 *****
2025-10-08 15:54:43.215680 | controller | changed: [instance]
2025-10-08 15:54:43.215999 | controller |
2025-10-08 15:54:43.298046 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-10-08 15:54:43.298087 | controller | Wednesday 08 October 2025  15:54:43 +0000 (0:00:08.260)       0:05:28.341 *****
2025-10-08 15:54:43.298099 | controller |
2025-10-08 15:54:43.820839 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-10-08 15:54:43.820874 | controller | Wednesday 08 October 2025  15:54:43 +0000 (0:00:00.082)       0:05:28.423 *****
2025-10-08 15:54:43.820886 | controller | ok: [instance] => (item=artifacts)
2025-10-08 15:54:45.060471 | controller | ok: [instance] => (item=logs)
2025-10-08 15:54:45.060510 | controller |
2025-10-08 15:54:45.060519 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-10-08 15:54:45.060526 | controller | Wednesday 08 October 2025  15:54:43 +0000 (0:00:00.522)       0:05:28.946 *****
2025-10-08 15:54:45.060537 | controller | ok: [instance]
2025-10-08 15:54:45.279184 | controller |
2025-10-08 15:54:45.279219 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-10-08 15:54:45.279228 | controller | Wednesday 08 October 2025  15:54:45 +0000 (0:00:01.238)       0:05:30.185 *****
2025-10-08 15:54:45.279244 | controller | changed: [instance]
2025-10-08 15:54:45.279264 | controller |
2025-10-08 15:54:45.279704 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-10-08 15:54:45.674129 | controller | Wednesday 08 October 2025  15:54:45 +0000 (0:00:00.216)       0:05:30.402 *****
2025-10-08 15:54:45.674168 | controller | changed: [instance]
2025-10-08 15:54:45.674201 | controller |
2025-10-08 15:54:45.674323 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-10-08 15:54:45.674481 | controller | Wednesday 08 October 2025  15:54:45 +0000 (0:00:00.395)       0:05:30.797 *****
2025-10-08 15:54:46.049257 | controller | changed: [instance]
2025-10-08 15:54:46.049434 | controller |
2025-10-08 15:54:46.049672 | controller | TASK [config_drive : Generate network-data] ************************************
2025-10-08 15:54:46.445418 | controller | Wednesday 08 October 2025  15:54:46 +0000 (0:00:00.377)       0:05:31.175 *****
2025-10-08 15:54:46.445453 | controller | changed: [instance]
2025-10-08 15:54:46.446109 | controller |
2025-10-08 15:54:46.446522 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-10-08 15:54:46.638599 | controller | Wednesday 08 October 2025  15:54:46 +0000 (0:00:00.391)       0:05:31.567 *****
2025-10-08 15:54:46.638634 | controller | ok: [instance]
2025-10-08 15:54:46.656727 | controller |
2025-10-08 15:54:46.656753 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-10-08 15:54:46.656761 | controller | Wednesday 08 October 2025  15:54:46 +0000 (0:00:00.194)       0:05:31.762 *****
2025-10-08 15:54:46.656771 | controller | skipping: [instance]
2025-10-08 15:54:46.874713 | controller |
2025-10-08 15:54:46.874747 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-10-08 15:54:46.874755 | controller | Wednesday 08 October 2025  15:54:46 +0000 (0:00:00.020)       0:05:31.783 *****
2025-10-08 15:54:46.874766 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-08 15:54:47.169349 | controller | changed: [instance]
2025-10-08 15:54:47.169418 | controller |
2025-10-08 15:54:47.169426 | controller | TASK [Define test-node VM] *****************************************************
2025-10-08 15:54:47.169433 | controller | Wednesday 08 October 2025  15:54:46 +0000 (0:00:00.217)       0:05:32.000 *****
2025-10-08 15:54:47.169442 | controller | changed: [instance]
2025-10-08 15:54:47.945482 | controller |
2025-10-08 15:54:47.945522 | controller | TASK [Start test-node VM] ******************************************************
2025-10-08 15:54:47.945537 | controller | Wednesday 08 October 2025  15:54:47 +0000 (0:00:00.294)       0:05:32.295 *****
2025-10-08 15:54:47.945548 | controller | changed: [instance]
2025-10-08 15:54:47.945568 | controller |
2025-10-08 15:54:47.945667 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-10-08 15:54:47.945761 | controller | Wednesday 08 October 2025  15:54:47 +0000 (0:00:00.776)       0:05:33.071 *****
2025-10-08 15:55:17.650993 | controller | ok: [instance]
2025-10-08 15:55:17.671255 | controller |
2025-10-08 15:55:17.671287 | controller | TASK [Add test node to inventory] **********************************************
2025-10-08 15:55:17.671295 | controller | Wednesday 08 October 2025  15:55:17 +0000 (0:00:29.705)       0:06:02.776 *****
2025-10-08 15:55:17.671306 | controller | changed: [instance]
2025-10-08 15:55:17.692152 | controller |
2025-10-08 15:55:17.692183 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-10-08 15:55:17.692192 | controller | Wednesday 08 October 2025  15:55:17 +0000 (0:00:00.020)       0:06:02.797 *****
2025-10-08 15:55:17.692202 | controller | changed: [instance]
2025-10-08 15:55:37.734613 | controller |
2025-10-08 15:55:37.734667 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-10-08 15:55:37.734687 | controller | Wednesday 08 October 2025  15:55:17 +0000 (0:00:00.020)       0:06:02.818 *****
2025-10-08 15:55:37.734700 | controller | Pausing for 20 seconds
2025-10-08 15:55:44.437564 | controller | ok: [instance]
2025-10-08 15:55:44.437597 | controller |
2025-10-08 15:55:44.437606 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-10-08 15:55:44.437613 | controller | Wednesday 08 October 2025  15:55:37 +0000 (0:00:20.041)       0:06:22.860 *****
2025-10-08 15:55:44.437623 | controller | changed: [instance]
2025-10-08 15:55:45.601260 | controller |
2025-10-08 15:55:45.601292 | controller | TASK [Grab some info from the test node] ***************************************
2025-10-08 15:55:45.601301 | controller | Wednesday 08 October 2025  15:55:44 +0000 (0:00:06.703)       0:06:29.563 *****
2025-10-08 15:55:45.601311 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-08 15:55:45.601373 | controller |
2025-10-08 15:55:45.601621 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-10-08 15:55:46.660589 | controller | Wednesday 08 October 2025  15:55:45 +0000 (0:00:01.163)       0:06:30.727 *****
2025-10-08 15:55:46.660624 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-08 15:55:47.267671 | controller |
2025-10-08 15:55:47.267706 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-10-08 15:55:47.267715 | controller | Wednesday 08 October 2025  15:55:46 +0000 (0:00:01.059)       0:06:31.786 *****
2025-10-08 15:55:47.267725 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-10-08 15:55:47.777694 | controller |
2025-10-08 15:55:47.777728 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-10-08 15:55:47.777737 | controller | Wednesday 08 October 2025  15:55:47 +0000 (0:00:00.607)       0:06:32.393 *****
2025-10-08 15:55:47.777748 | controller | changed: [instance]
2025-10-08 15:55:48.125503 | controller |
2025-10-08 15:55:48.125536 | controller | TASK [Write test-node info to file] ********************************************
2025-10-08 15:55:48.125544 | controller | Wednesday 08 October 2025  15:55:47 +0000 (0:00:00.509)       0:06:32.903 *****
2025-10-08 15:55:48.125554 | controller | changed: [instance]
2025-10-08 15:55:48.494747 | controller |
2025-10-08 15:55:48.494780 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-10-08 15:55:48.494788 | controller | Wednesday 08 October 2025  15:55:48 +0000 (0:00:00.348)       0:06:33.251 *****
2025-10-08 15:55:48.494798 | controller | changed: [instance]
2025-10-08 15:55:48.494833 | controller |
2025-10-08 15:55:48.495075 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-10-08 15:55:48.835761 | controller | Wednesday 08 October 2025  15:55:48 +0000 (0:00:00.369)       0:06:33.621 *****
2025-10-08 15:55:48.835796 | controller | changed: [instance]
2025-10-08 15:55:49.167306 | controller |
2025-10-08 15:55:49.167372 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-10-08 15:55:49.167386 | controller | Wednesday 08 October 2025  15:55:48 +0000 (0:00:00.340)       0:06:33.961 *****
2025-10-08 15:55:49.167397 | controller | changed: [instance]
2025-10-08 15:55:49.518961 | controller |
2025-10-08 15:55:49.519005 | controller | TASK [Write hypervisor info to file] *******************************************
2025-10-08 15:55:49.519014 | controller | Wednesday 08 October 2025  15:55:49 +0000 (0:00:00.331)       0:06:34.293 *****
2025-10-08 15:55:49.519024 | controller | changed: [instance]
2025-10-08 15:55:51.187814 | controller |
2025-10-08 15:55:51.187853 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-10-08 15:55:51.187865 | controller | Wednesday 08 October 2025  15:55:49 +0000 (0:00:00.351)       0:06:34.644 *****
2025-10-08 15:55:51.187875 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-10-08 15:55:51.234433 | controller |
2025-10-08 15:55:51.234492 | controller | TASK [Debug the ping example.com result] ***************************************
2025-10-08 15:55:51.234501 | controller | Wednesday 08 October 2025  15:55:51 +0000 (0:00:01.668)       0:06:36.313 *****
2025-10-08 15:55:51.234517 | controller | ok: [instance] => (item=0) =>
2025-10-08 15:55:51.234575 | controller |   msg: '0'
2025-10-08 15:55:51.234587 | controller | ok: [instance] => (item=['PING example.com(a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a)) 56 data bytes', '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=1 ttl=45 time=33.4 ms', '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=2 ttl=45 time=34.2 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 33.438/33.805/34.173/0.367 ms']) =>
2025-10-08 15:55:51.234694 | controller |   msg:
2025-10-08 15:55:51.234704 | controller |   - PING example.com(a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a)) 56 data bytes
2025-10-08 15:55:51.234710 | controller |   - '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=1 ttl=45 time=33.4 ms'
2025-10-08 15:55:51.234716 | controller |   - '64 bytes from a23-215-0-138.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17d7:8a): icmp_seq=2 ttl=45 time=34.2 ms'
2025-10-08 15:55:51.234721 | controller |   - ''
2025-10-08 15:55:51.234727 | controller |   - '--- example.com ping statistics ---'
2025-10-08 15:55:51.234733 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-10-08 15:55:51.234739 | controller |   - rtt min/avg/max/mdev = 33.438/33.805/34.173/0.367 ms
2025-10-08 15:55:51.234745 | controller | ok: [instance] => (item=[]) =>
2025-10-08 15:55:51.234750 | controller |   msg: []
2025-10-08 15:55:51.234756 | controller |
2025-10-08 15:55:51.234761 | controller | PLAY RECAP *********************************************************************
2025-10-08 15:55:51.234767 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-10-08 15:55:51.234772 | controller |
2025-10-08 15:55:51.234777 | controller | Wednesday 08 October 2025  15:55:51 +0000 (0:00:00.044)       0:06:36.357 *****
2025-10-08 15:55:51.234783 | controller | ===============================================================================
2025-10-08 15:55:51.234788 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 250.32s
2025-10-08 15:55:51.234794 | controller | Wait for test node to be reachable via ssh ----------------------------- 29.71s
2025-10-08 15:55:51.234799 | controller | Download latest image -------------------------------------------------- 20.60s
2025-10-08 15:55:51.234818 | controller | Wait a little to let the test instance boot. --------------------------- 20.04s
2025-10-08 15:55:51.234825 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir -------------- 10.13s
2025-10-08 15:55:51.234838 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.26s
2025-10-08 15:55:51.234843 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.26s
2025-10-08 15:55:51.234849 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.40s
2025-10-08 15:55:51.234854 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.70s
2025-10-08 15:55:51.234859 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.60s
2025-10-08 15:55:51.234865 | controller | discover_latest_image : Get latest image -------------------------------- 1.73s
2025-10-08 15:55:51.234870 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.67s
2025-10-08 15:55:51.234876 | controller | config_drive : Install required RPM packages ---------------------------- 1.32s
2025-10-08 15:55:51.234881 | controller | config_drive : Install required RPM packages ---------------------------- 1.24s
2025-10-08 15:55:51.234887 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.23s
2025-10-08 15:55:51.234895 | controller | Grab some info from the test node --------------------------------------- 1.16s
2025-10-08 15:55:51.234918 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.13s
2025-10-08 15:55:51.234927 | controller | Grab some info from the nat64 appliance --------------------------------- 1.06s
2025-10-08 15:55:51.235044 | controller | Restart firewalld.service ----------------------------------------------- 1.01s
2025-10-08 15:55:51.235164 | controller | nat64_appliance : Restart firewalld.service ----------------------------- 0.88s
2025-10-08 15:55:51.298495 | controller | INFO     Running default > cleanup
2025-10-08 15:55:51.770611 | controller |
2025-10-08 15:55:51.770669 | controller | PLAY [Cleanup] *****************************************************************
2025-10-08 15:55:51.770680 | controller |
2025-10-08 15:55:51.770688 | controller | TASK [Gathering Facts] *********************************************************
2025-10-08 15:55:51.770697 | controller | Wednesday 08 October 2025  15:55:51 +0000 (0:00:00.052)       0:00:00.052 *****
2025-10-08 15:55:52.704453 | controller | ok: [instance]
2025-10-08 15:55:52.704518 | controller |
2025-10-08 15:55:52.704777 | controller | TASK [Destroy the test-node] ***************************************************
2025-10-08 15:55:53.269119 | controller | Wednesday 08 October 2025  15:55:52 +0000 (0:00:00.934)       0:00:00.987 *****
2025-10-08 15:55:53.269157 | controller | ok: [instance]
2025-10-08 15:55:53.502057 | controller |
2025-10-08 15:55:53.502090 | controller | TASK [Undefine the test-node] **************************************************
2025-10-08 15:55:53.502098 | controller | Wednesday 08 October 2025  15:55:53 +0000 (0:00:00.564)       0:00:01.551 *****
2025-10-08 15:55:53.502108 | controller | ok: [instance]
2025-10-08 15:55:53.871395 | controller |
2025-10-08 15:55:53.871427 | controller | TASK [Destroy the test network] ************************************************
2025-10-08 15:55:53.871435 | controller | Wednesday 08 October 2025  15:55:53 +0000 (0:00:00.233)       0:00:01.784 *****
2025-10-08 15:55:53.871446 | controller | ok: [instance]
2025-10-08 15:55:54.094458 | controller |
2025-10-08 15:55:54.094497 | controller | TASK [Undefine the test network] ***********************************************
2025-10-08 15:55:54.094506 | controller | Wednesday 08 October 2025  15:55:53 +0000 (0:00:00.369)       0:00:02.153 *****
2025-10-08 15:55:54.094517 | controller | ok: [instance]
2025-10-08 15:55:54.127198 | controller |
2025-10-08 15:55:54.127234 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-10-08 15:55:54.127243 | controller | Wednesday 08 October 2025  15:55:54 +0000 (0:00:00.223)       0:00:02.376 *****
2025-10-08 15:55:54.127253 | controller |
2025-10-08 15:55:54.445381 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-10-08 15:55:54.445421 | controller | Wednesday 08 October 2025  15:55:54 +0000 (0:00:00.032)       0:00:02.409 *****
2025-10-08 15:55:54.445434 | controller | changed: [instance]
2025-10-08 15:55:54.734264 | controller |
2025-10-08 15:55:54.734296 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-10-08 15:55:54.734304 | controller | Wednesday 08 October 2025  15:55:54 +0000 (0:00:00.318)       0:00:02.727 *****
2025-10-08 15:55:54.734319 | controller | ok: [instance]
2025-10-08 15:55:54.971472 | controller |
2025-10-08 15:55:54.971506 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-10-08 15:55:54.971515 | controller | Wednesday 08 October 2025  15:55:54 +0000 (0:00:00.288)       0:00:03.016 *****
2025-10-08 15:55:54.971525 | controller | ok: [instance]
2025-10-08 15:55:55.634842 | controller |
2025-10-08 15:55:55.634875 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-10-08 15:55:55.634884 | controller | Wednesday 08 October 2025  15:55:54 +0000 (0:00:00.237)       0:00:03.253 *****
2025-10-08 15:55:55.634894 | controller | ok: [instance]
2025-10-08 15:55:55.867054 | controller |
2025-10-08 15:55:55.867084 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-10-08 15:55:55.867094 | controller | Wednesday 08 October 2025  15:55:55 +0000 (0:00:00.663)       0:00:03.917 *****
2025-10-08 15:55:55.867110 | controller | ok: [instance]
2025-10-08 15:55:56.654437 | controller |
2025-10-08 15:55:56.654482 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-10-08 15:55:56.654491 | controller | Wednesday 08 October 2025  15:55:55 +0000 (0:00:00.232)       0:00:04.149 *****
2025-10-08 15:55:56.654502 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-08 15:55:57.120571 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-08 15:55:57.120604 | controller |
2025-10-08 15:55:57.120613 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-10-08 15:55:57.120619 | controller | Wednesday 08 October 2025  15:55:56 +0000 (0:00:00.787)       0:00:04.936 *****
2025-10-08 15:55:57.120629 | controller | ok: [instance] => (item=nat64-net-v4)
2025-10-08 15:55:57.120662 | controller | ok: [instance] => (item=nat64-net-v6)
2025-10-08 15:55:57.122538 | controller |
2025-10-08 15:55:57.169809 | controller | PLAY RECAP *********************************************************************
2025-10-08 15:55:57.169847 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-10-08 15:55:57.169855 | controller |
2025-10-08 15:55:57.169861 | controller | Wednesday 08 October 2025  15:55:57 +0000 (0:00:00.466)       0:00:05.403 *****
2025-10-08 15:55:57.169867 | controller | ===============================================================================
2025-10-08 15:55:57.169873 | controller | Gathering Facts --------------------------------------------------------- 0.93s
2025-10-08 15:55:57.169878 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.79s
2025-10-08 15:55:57.169883 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.66s
2025-10-08 15:55:57.169889 | controller | Destroy the test-node --------------------------------------------------- 0.56s
2025-10-08 15:55:57.169894 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.47s
2025-10-08 15:55:57.169899 | controller | Destroy the test network ------------------------------------------------ 0.37s
2025-10-08 15:55:57.169905 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.32s
2025-10-08 15:55:57.169910 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.29s
2025-10-08 15:55:57.169915 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.24s
2025-10-08 15:55:57.169921 | controller | Undefine the test-node -------------------------------------------------- 0.23s
2025-10-08 15:55:57.169926 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.23s
2025-10-08 15:55:57.169931 | controller | Undefine the test network ----------------------------------------------- 0.22s
2025-10-08 15:55:57.169937 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-10-08 15:55:57.169947 | controller | INFO     Writing /tmp/report.html report.
2025-10-08 15:55:57.252837 | [controller] Waiting on logger
2025-10-08 15:56:02.418331 | [controller] Waiting on logger
2025-10-08 15:56:12.850387 | [controller] Waiting on logger
2025-10-08 15:56:23.283412 | [controller] Waiting on logger
2025-10-08 15:56:25.650646 | controller | changed
2025-10-08 15:56:25.679955 | 
2025-10-08 15:56:25.680048 | PLAY RECAP
2025-10-08 15:56:25.680094 | controller | ok: 3 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-08 15:56:25.680118 | 
2025-10-08 15:56:25.778105 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-10-08 15:56:25.778961 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 15:56:26.445338 | 
2025-10-08 15:56:26.445442 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-10-08 15:56:26.466585 | 
2025-10-08 15:56:26.466696 | TASK [Filter out host if needed]
2025-10-08 15:56:26.475790 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-10-08 15:56:26.480843 | 
2025-10-08 15:56:26.480943 | TASK [Ensure file is present]
2025-10-08 15:56:26.834075 | controller | ok
2025-10-08 15:56:26.841220 | 
2025-10-08 15:56:26.841308 | TASK [Manage molecule report file]
2025-10-08 15:56:26.865242 | [controller] Waiting on logger
2025-10-08 15:56:37.298444 | [controller] Waiting on logger
2025-10-08 15:56:46.642321 | [controller] Waiting on logger
2025-10-08 15:56:57.074494 | [controller] Waiting on logger
2025-10-08 15:56:57.191149 | [Zuul] Log Stream did not terminate
2025-10-08 15:56:57.191335 | controller | changed
2025-10-08 15:56:57.196526 | 
2025-10-08 15:56:57.196709 | TASK [Check if we get ci-framework-data basedir]
2025-10-08 15:56:57.387951 | controller | ok
2025-10-08 15:56:57.394010 | 
2025-10-08 15:56:57.394179 | TASK [Create ci-framework-data log directory for zuul]
2025-10-08 15:56:57.720091 | controller | changed
2025-10-08 15:56:57.725445 | 
2025-10-08 15:56:57.725514 | TASK [Copy ci-framework interesting files]
2025-10-08 15:56:57.750666 | [controller] Waiting on logger
2025-10-08 15:57:05.123541 | controller | changed
2025-10-08 15:57:05.128728 | 
2025-10-08 15:57:05.128803 | TASK [Get SELinux listing]
2025-10-08 15:57:09.555312 | [controller] Waiting on logger
2025-10-08 15:57:10.155122 | controller | changed
2025-10-08 15:57:10.162010 | 
2025-10-08 15:57:10.162095 | TASK [Generate log index]
2025-10-08 15:57:10.861952 | controller | changed
2025-10-08 15:57:10.867482 | 
2025-10-08 15:57:10.867561 | TASK [Get some env related data]
2025-10-08 15:57:13.970467 | [controller] Waiting on logger
2025-10-08 15:57:27.218358 | [controller] Waiting on logger
2025-10-08 15:57:30.084581 | controller | changed
2025-10-08 15:57:30.090105 | 
2025-10-08 15:57:30.090187 | TASK [Generate list of logs to collect in home directory]
2025-10-08 15:57:30.454031 | controller | ok: All paths examined
2025-10-08 15:57:30.469458 | 
2025-10-08 15:57:30.469551 | LOOP [Copy logs from home directory]
2025-10-08 15:57:30.864516 | controller | changed:
2025-10-08 15:57:30.864706 | controller | {
2025-10-08 15:57:30.864742 | controller |   "atime": 1759938363.7289388,
2025-10-08 15:57:30.864765 | controller |   "ctime": 1759938379.9618683,
2025-10-08 15:57:30.864784 | controller |   "dev": 64513,
2025-10-08 15:57:30.864801 | controller |   "gid": 1000,
2025-10-08 15:57:30.864816 | controller |   "gr_name": "zuul",
2025-10-08 15:57:30.864831 | controller |   "inode": 4454385,
2025-10-08 15:57:30.864856 | controller |   "isblk": false,
2025-10-08 15:57:30.864871 | controller |   "ischr": false,
2025-10-08 15:57:30.864884 | controller |   "isdir": false,
2025-10-08 15:57:30.864952 | controller |   "isfifo": false,
2025-10-08 15:57:30.864978 | controller |   "isgid": false,
2025-10-08 15:57:30.865009 | controller |   "islnk": false,
2025-10-08 15:57:30.865028 | controller |   "isreg": true,
2025-10-08 15:57:30.865044 | controller |   "issock": false,
2025-10-08 15:57:30.865058 | controller |   "isuid": false,
2025-10-08 15:57:30.865072 | controller |   "mode": "0644",
2025-10-08 15:57:30.865086 | controller |   "mtime": 1759938379.9618683,
2025-10-08 15:57:30.865100 | controller |   "nlink": 1,
2025-10-08 15:57:30.865113 | controller |   "path": "/home/zuul/ansible.log",
2025-10-08 15:57:30.865127 | controller |   "pw_name": "zuul",
2025-10-08 15:57:30.865143 | controller |   "rgrp": true,
2025-10-08 15:57:30.865158 | controller |   "roth": true,
2025-10-08 15:57:30.865171 | controller |   "rusr": true,
2025-10-08 15:57:30.865185 | controller |   "size": 6749,
2025-10-08 15:57:30.865198 | controller |   "uid": 1000,
2025-10-08 15:57:30.865225 | controller |   "wgrp": false,
2025-10-08 15:57:30.865239 | controller |   "woth": false,
2025-10-08 15:57:30.865252 | controller |   "wusr": true,
2025-10-08 15:57:30.865267 | controller |   "xgrp": false,
2025-10-08 15:57:30.865282 | controller |   "xoth": false,
2025-10-08 15:57:30.865297 | controller |   "xusr": false
2025-10-08 15:57:30.865311 | controller | }
2025-10-08 15:57:30.875709 | 
2025-10-08 15:57:30.875776 | TASK [Copy crio stats log file]
2025-10-08 15:57:30.899382 | controller | skipping: Conditional result was False
2025-10-08 15:57:30.904860 | 
2025-10-08 15:57:30.904994 | TASK [Get SELinux related data]
2025-10-08 15:57:34.002332 | [controller] Waiting on logger
2025-10-08 15:57:43.382894 | [controller] Waiting on logger
2025-10-08 15:57:53.779335 | [controller] Waiting on logger
2025-10-08 15:58:01.159610 | [Zuul] Log Stream did not terminate
2025-10-08 15:58:01.159967 | controller | ERROR
2025-10-08 15:58:01.160118 | controller | {
2025-10-08 15:58:01.160153 | controller |   "delta": "0:00:00.009637",
2025-10-08 15:58:01.160174 | controller |   "end": "2025-10-08 15:57:31.128676",
2025-10-08 15:58:01.160192 | controller |   "msg": "non-zero return code",
2025-10-08 15:58:01.160208 | controller |   "rc": 1,
2025-10-08 15:58:01.160242 | controller |   "start": "2025-10-08 15:57:31.119039"
2025-10-08 15:58:01.160259 | controller | }
2025-10-08 15:58:01.160285 | controller | ERROR: Ignoring Errors
2025-10-08 15:58:01.166119 | 
2025-10-08 15:58:01.166208 | TASK [Create system configuration directory]
2025-10-08 15:58:01.369614 | controller | changed
2025-10-08 15:58:01.374675 | 
2025-10-08 15:58:01.374761 | TASK [Get some of the system configurations]
2025-10-08 15:58:01.395973 | [controller] Waiting on logger
2025-10-08 15:58:11.826487 | [controller] Waiting on logger
2025-10-08 15:58:22.258361 | [controller] Waiting on logger
2025-10-08 15:58:31.602466 | [controller] Waiting on logger
2025-10-08 15:58:31.619238 | [Zuul] Log Stream did not terminate
2025-10-08 15:58:31.619424 | controller | changed
2025-10-08 15:58:31.624715 | 
2025-10-08 15:58:31.624781 | TASK [Copy generated documentation if available]
2025-10-08 15:58:31.648780 | controller | skipping: Conditional result was False
2025-10-08 15:58:31.655161 | 
2025-10-08 15:58:31.655281 | TASK [Copy generated AsciiDoc documentation if available]
2025-10-08 15:58:31.699413 | controller | skipping: Conditional result was False
2025-10-08 15:58:31.706484 | 
2025-10-08 15:58:31.706580 | TASK [Compress logs bigger than 2MB]
2025-10-08 15:58:32.754405 | [controller] Waiting on logger
2025-10-08 15:58:45.234368 | [controller] Waiting on logger
2025-10-08 15:58:54.578427 | [controller] Waiting on logger
2025-10-08 15:59:01.931353 | [Zuul] Log Stream did not terminate
2025-10-08 15:59:01.931507 | controller | changed
2025-10-08 15:59:01.936783 | 
2025-10-08 15:59:01.936848 | TASK [Copy files from workspace on node]
2025-10-08 15:59:01.955570 | controller | ok
2025-10-08 15:59:01.979081 | 
2025-10-08 15:59:01.979279 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 15:59:01.992823 | controller | skipping: Conditional result was False
2025-10-08 15:59:01.999196 | 
2025-10-08 15:59:01.999306 | TASK [fetch-output : Set log path for single node]
2025-10-08 15:59:02.028934 | controller | ok
2025-10-08 15:59:02.034224 | 
2025-10-08 15:59:02.034314 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 15:59:02.283000 | controller -> localhost | ok: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/logs"
2025-10-08 15:59:02.283254 | controller -> localhost | changed: All items complete
2025-10-08 15:59:02.283294 | 
2025-10-08 15:59:02.473442 | controller -> localhost | changed: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/artifacts"
2025-10-08 15:59:02.678308 | controller -> localhost | changed: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/docs"
2025-10-08 15:59:02.695863 | 
2025-10-08 15:59:02.695979 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 15:59:03.305272 | controller | changed:
2025-10-08 15:59:03.305522 | controller | .d..t...... ./
2025-10-08 15:59:03.305553 | controller | >f+++++++++ README.html
2025-10-08 15:59:03.305575 | controller | >f+++++++++ ansible-execution.log
2025-10-08 15:59:03.305597 | controller | >f+++++++++ ansible.log
2025-10-08 15:59:03.305616 | controller | >f+++++++++ dmesg.log
2025-10-08 15:59:03.305635 | controller | >f+++++++++ installed-pkgs.log
2025-10-08 15:59:03.305654 | controller | >f+++++++++ python.log
2025-10-08 15:59:03.305672 | controller | >f+++++++++ registries.conf
2025-10-08 15:59:03.305688 | controller | >f+++++++++ report.html
2025-10-08 15:59:03.306328 | controller | >f+++++++++ selinux-denials.log
2025-10-08 15:59:03.306384 | controller | >f+++++++++ selinux-listing.log
2025-10-08 15:59:03.306409 | controller | cd+++++++++ ci-framework-data/
2025-10-08 15:59:03.306429 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-10-08 15:59:03.306473 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-10-08 15:59:03.306495 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-10-08 15:59:03.306513 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-10-08 15:59:03.306560 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-10-08 15:59:03.306579 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-10-08 15:59:03.306596 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/9fd5b72f-7746-546b-af11-06e17fb39fbb/
2025-10-08 15:59:03.306635 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/9fd5b72f-7746-546b-af11-06e17fb39fbb/meta-data
2025-10-08 15:59:03.306654 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/9fd5b72f-7746-546b-af11-06e17fb39fbb/network-config
2025-10-08 15:59:03.306671 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/9fd5b72f-7746-546b-af11-06e17fb39fbb/user-data
2025-10-08 15:59:03.306708 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c27bc23a-6781-5578-9983-c331f41b795b/
2025-10-08 15:59:03.306728 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c27bc23a-6781-5578-9983-c331f41b795b/meta-data
2025-10-08 15:59:03.306744 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c27bc23a-6781-5578-9983-c331f41b795b/network-config
2025-10-08 15:59:03.306761 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/c27bc23a-6781-5578-9983-c331f41b795b/user-data
2025-10-08 15:59:03.306806 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-10-08 15:59:03.306823 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-10-08 15:59:03.306838 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-10-08 15:59:03.306878 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-10-08 15:59:03.306897 | controller | cd+++++++++ ci-framework-data/logs/
2025-10-08 15:59:03.307020 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-10-08 15:59:03.307083 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-10-08 15:59:03.307108 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-10-08 15:59:03.307126 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-10-08 15:59:03.307142 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-10-08 15:59:03.307158 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-10-08 15:59:03.307173 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-10-08 15:59:03.307190 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-10-08 15:59:03.307205 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-10-08 15:59:03.307220 | controller | cd+++++++++ registries.conf.d/
2025-10-08 15:59:03.307248 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-10-08 15:59:03.307264 | controller | cd+++++++++ system-config/
2025-10-08 15:59:03.307280 | controller | cd+++++++++ system-config/libvirt/
2025-10-08 15:59:03.307296 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-10-08 15:59:03.307311 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-10-08 15:59:03.307326 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-10-08 15:59:03.307341 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-10-08 15:59:03.307356 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-10-08 15:59:03.307371 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-10-08 15:59:03.307386 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-10-08 15:59:03.307401 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-10-08 15:59:03.307415 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-10-08 15:59:03.307429 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-10-08 15:59:03.307442 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-10-08 15:59:03.307456 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-10-08 15:59:03.307470 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-10-08 15:59:03.307484 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-10-08 15:59:03.307498 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-10-08 15:59:03.307512 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-10-08 15:59:03.688884 | controller | changed: .d..t...... ./
2025-10-08 15:59:04.078201 | controller | changed: .d..t...... ./
2025-10-08 15:59:04.093540 | 
2025-10-08 15:59:04.093617 | TASK [Return artifact to Zuul]
2025-10-08 15:59:04.122175 | controller | ok
2025-10-08 15:59:04.141696 | 
2025-10-08 15:59:04.141759 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-10-08 15:59:04.141863 | 
2025-10-08 15:59:04.141890 | PLAY RECAP
2025-10-08 15:59:04.141949 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-10-08 15:59:04.141974 | 
2025-10-08 15:59:04.239110 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-10-08 15:59:04.239933 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 15:59:04.797843 | 
2025-10-08 15:59:04.797970 | PLAY [all]
2025-10-08 15:59:04.817069 | 
2025-10-08 15:59:04.817143 | TASK [include_role : fetch-output]
2025-10-08 15:59:04.845780 | controller | ok
2025-10-08 15:59:04.863580 | 
2025-10-08 15:59:04.863666 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-08 15:59:04.907883 | controller | skipping: Conditional result was False
2025-10-08 15:59:04.913688 | 
2025-10-08 15:59:04.913762 | TASK [fetch-output : Set log path for single node]
2025-10-08 15:59:04.942398 | controller | ok
2025-10-08 15:59:04.947347 | 
2025-10-08 15:59:04.947416 | LOOP [fetch-output : Ensure local output dirs]
2025-10-08 15:59:05.335161 | controller -> localhost | ok: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/logs"
2025-10-08 15:59:05.507851 | controller -> localhost | ok: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/artifacts"
2025-10-08 15:59:05.702452 | controller -> localhost | ok: "/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/docs"
2025-10-08 15:59:05.717212 | 
2025-10-08 15:59:05.717313 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-08 15:59:06.242806 | controller | ok
2025-10-08 15:59:06.243003 | controller | ok: All items complete
2025-10-08 15:59:06.243034 | 
2025-10-08 15:59:06.640677 | controller | ok
2025-10-08 15:59:07.042970 | controller | ok
2025-10-08 15:59:07.057585 | 
2025-10-08 15:59:07.057712 | TASK [include_role : fetch-output-openshift]
2025-10-08 15:59:07.072292 | controller | skipping: Conditional result was False
2025-10-08 15:59:07.079630 | 
2025-10-08 15:59:07.079708 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-08 15:59:07.497748 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006082
2025-10-08 15:59:07.723100 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.009414
2025-10-08 15:59:07.765286 | 
2025-10-08 15:59:07.765377 | PLAY [all]
2025-10-08 15:59:07.780272 | 
2025-10-08 15:59:07.780357 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-08 15:59:08.206439 | controller | changed
2025-10-08 15:59:08.230152 | 
2025-10-08 15:59:08.230227 | PLAY RECAP
2025-10-08 15:59:08.230288 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-08 15:59:08.230314 | 
2025-10-08 15:59:08.306085 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-08 15:59:08.306862 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-08 15:59:08.896025 | 
2025-10-08 15:59:08.896132 | PLAY [localhost]
2025-10-08 15:59:08.914339 | 
2025-10-08 15:59:08.914422 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-08 15:59:09.246628 | localhost | changed
2025-10-08 15:59:09.251437 | 
2025-10-08 15:59:09.251528 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-08 15:59:09.280063 | localhost | ok
2025-10-08 15:59:09.288410 | 
2025-10-08 15:59:09.288506 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-08 15:59:09.610787 | localhost | changed
2025-10-08 15:59:09.616940 | 
2025-10-08 15:59:09.617021 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-08 15:59:10.203451 | localhost | changed
2025-10-08 15:59:10.209526 | 
2025-10-08 15:59:10.209638 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-08 15:59:10.583573 | localhost | Identity added: /var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/tmp/ansible.umrbqkrd (/var/lib/zuul/builds/4976c3651bdd44e3b2e446550411f3c7/work/tmp/ansible.umrbqkrd)
2025-10-08 15:59:10.583747 | localhost | ok: Runtime: 0:00:00.013299
2025-10-08 15:59:10.588769 | 
2025-10-08 15:59:10.588848 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-08 15:59:10.820328 | localhost | ok: Runtime: 0:00:00.011206
2025-10-08 15:59:10.825524 | 
2025-10-08 15:59:10.825612 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-08 15:59:10.876269 | localhost | changed
2025-10-08 15:59:10.881602 | 
2025-10-08 15:59:10.881705 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-08 15:59:11.234740 | localhost | changed
2025-10-08 15:59:11.256584 | 
2025-10-08 15:59:11.256715 | PLAY [localhost]
2025-10-08 15:59:11.268664 | 
2025-10-08 15:59:11.268859 | TASK [Generate bulk log download script]
2025-10-08 15:59:11.289362 | localhost | ok
2025-10-08 15:59:11.302311 | 
2025-10-08 15:59:11.302421 | TASK [local-log-download : Check API endpoint is defined]
2025-10-08 15:59:11.330796 | localhost | ok: All assertions passed
2025-10-08 15:59:11.335465 | 
2025-10-08 15:59:11.335534 | TASK [local-log-download : Create download script]
2025-10-08 15:59:11.736424 | localhost -> localhost | changed
2025-10-08 15:59:11.746768 | 
2025-10-08 15:59:11.746871 | TASK [Register quick-download link]
2025-10-08 15:59:11.765463 | localhost | ok
2025-10-08 15:59:11.806303 | 
2025-10-08 15:59:11.806397 | PLAY [logserver.rdoproject.org]
2025-10-08 15:59:11.817175 | 
2025-10-08 15:59:11.817271 | TASK [Set zuul-log-path fact]
2025-10-08 15:59:11.834026 | logserver.rdoproject.org | ok
2025-10-08 15:59:11.845156 | 
2025-10-08 15:59:11.845265 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-08 15:59:11.872332 | logserver.rdoproject.org | ok
2025-10-08 15:59:11.877591 | 
2025-10-08 15:59:11.877660 | TASK [upload-logs : Create log directories]
2025-10-08 15:59:13.593385 | logserver.rdoproject.org | changed
2025-10-08 15:59:13.596993 | 
2025-10-08 15:59:13.597060 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-08 15:59:13.844860 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004403
2025-10-08 15:59:13.849564 | 
2025-10-08 15:59:13.849630 | TASK [upload-logs : Upload logs to log server]
2025-10-08 15:59:15.461224 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-08 15:59:15.464280 | 
2025-10-08 15:59:15.464371 | LOOP [upload-logs : Compress console log and json output]
2025-10-08 15:59:15.508744 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 15:59:15.518741 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 15:59:15.526171 | 
2025-10-08 15:59:15.526309 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-08 15:59:15.582501 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 15:59:15.582703 | 
2025-10-08 15:59:15.583372 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-08 15:59:15.596108 | 
2025-10-08 15:59:15.596223 | LOOP [upload-logs : Upload console log and json output]