2025-11-26 07:30:06.344221 | Job console starting...
2025-11-26 07:30:06.736056 | Updating repositories
2025-11-26 07:30:07.511700 | Preparing job workspace
2025-11-26 07:30:24.588749 | Running Ansible setup...
2025-11-26 07:30:31.391843 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-11-26 07:30:33.289250 | 
2025-11-26 07:30:33.289369 | PLAY [localhost]
2025-11-26 07:30:33.342919 | 
2025-11-26 07:30:33.343008 | TASK [Gathering Facts]
2025-11-26 07:30:36.391452 | localhost | ok
2025-11-26 07:30:36.419549 | 
2025-11-26 07:30:36.419653 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-26 07:30:37.522815 | localhost -> localhost | changed
2025-11-26 07:30:37.528404 | 
2025-11-26 07:30:37.528476 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-26 07:30:41.375060 | localhost -> localhost | changed
2025-11-26 07:30:41.389934 | 
2025-11-26 07:30:41.390011 | TASK [Setup log path fact]
2025-11-26 07:30:41.464253 | localhost | ok
2025-11-26 07:30:41.487438 | 
2025-11-26 07:30:41.487530 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-26 07:30:41.589776 | localhost | ok
2025-11-26 07:30:41.597258 | 
2025-11-26 07:30:41.597331 | TASK [emit-job-header : Print job information]
2025-11-26 07:30:41.782867 | # Job Information
2025-11-26 07:30:41.783034 | Ansible Version: 2.15.12
2025-11-26 07:30:41.783067 | Job: cifmw-molecule-nat64_appliance
2025-11-26 07:30:41.783091 | Pipeline: github-check
2025-11-26 07:30:41.783113 | Executor: ibm-bm3-ze.softwarefactory-project.io
2025-11-26 07:30:41.783133 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3505
2025-11-26 07:30:41.783154 | Log URL (when completed): https://logserver.rdoproject.org/04a/rdoproject.org/04a778c41bbc4932ba83f3752f617298/
2025-11-26 07:30:41.783174 | Event ID: 8adaaf80-ca99-11f0-898f-2010a17eda0e
2025-11-26 07:30:41.790349 | 
2025-11-26 07:30:41.790452 | LOOP [emit-job-header : Print node information]
2025-11-26 07:30:42.225911 | localhost | ok:
2025-11-26 07:30:42.226076 | localhost | # Node Information
2025-11-26 07:30:42.226108 | localhost | Inventory Hostname: controller
2025-11-26 07:30:42.226136 | localhost | Hostname: np0005536234
2025-11-26 07:30:42.226159 | localhost | Username: zuul
2025-11-26 07:30:42.226182 | localhost | Distro: CentOS 9
2025-11-26 07:30:42.226202 | localhost | Provider: ibm-bm3-nodepool
2025-11-26 07:30:42.226222 | localhost | Region: regionOne
2025-11-26 07:30:42.226240 | localhost | Label: cloud-centos-9-stream-tripleo-ibm
2025-11-26 07:30:42.226259 | localhost | Product Name: OpenStack Compute
2025-11-26 07:30:42.226278 | localhost | Interface IP: 192.168.25.53
2025-11-26 07:30:42.297876 | 
2025-11-26 07:30:42.297991 | PLAY [all]
2025-11-26 07:30:42.317366 | 
2025-11-26 07:30:42.317447 | TASK [Gather network facts]
2025-11-26 07:30:42.802505 | controller | ok
2025-11-26 07:30:42.837998 | 
2025-11-26 07:30:42.838070 | TASK [include_role : start-zuul-console]
2025-11-26 07:30:42.914213 | controller | ok
2025-11-26 07:30:42.956972 | 
2025-11-26 07:30:42.957057 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-26 07:30:44.045296 | controller | ok
2025-11-26 07:30:44.065716 | 
2025-11-26 07:30:44.065798 | TASK [include_role : add-build-sshkey]
2025-11-26 07:30:44.160561 | controller | ok
2025-11-26 07:30:44.224020 | 
2025-11-26 07:30:44.224115 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-26 07:30:45.099851 | controller -> localhost | ok
2025-11-26 07:30:45.107272 | 
2025-11-26 07:30:45.107341 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-26 07:30:45.188502 | controller | ok
2025-11-26 07:30:45.262793 | controller | included: /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-26 07:30:45.288754 | 
2025-11-26 07:30:45.288847 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-26 07:30:47.344740 | controller -> localhost | Generating public/private rsa key pair.
2025-11-26 07:30:47.344959 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/04a778c41bbc4932ba83f3752f617298_id_rsa.
2025-11-26 07:30:47.344998 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/04a778c41bbc4932ba83f3752f617298_id_rsa.pub.
2025-11-26 07:30:47.345025 | controller -> localhost | The key fingerprint is:
2025-11-26 07:30:47.345047 | controller -> localhost | SHA256:Ue06Yh7gsNCc7L3uRxMsWmZ9RLldfM1a1L1Z7cLvH2Q zuul-build-sshkey
2025-11-26 07:30:47.345070 | controller -> localhost | The key's randomart image is:
2025-11-26 07:30:47.345091 | controller -> localhost | +---[RSA 3072]----+
2025-11-26 07:30:47.345111 | controller -> localhost | |         .oo . o*|
2025-11-26 07:30:47.345130 | controller -> localhost | |         .o . o X|
2025-11-26 07:30:47.345150 | controller -> localhost | |   + . o.. + o =+|
2025-11-26 07:30:47.345170 | controller -> localhost | |  . * * +.o o +o.|
2025-11-26 07:30:47.345189 | controller -> localhost | |   o X oSo .   E |
2025-11-26 07:30:47.345208 | controller -> localhost | |    + o * o   o .|
2025-11-26 07:30:47.345225 | controller -> localhost | |       = + .   o |
2025-11-26 07:30:47.345245 | controller -> localhost | |      . o       o|
2025-11-26 07:30:47.345265 | controller -> localhost | |     oo.        o|
2025-11-26 07:30:47.345284 | controller -> localhost | +----[SHA256]-----+
2025-11-26 07:30:47.345328 | controller -> localhost | ok: Runtime: 0:00:00.239636
2025-11-26 07:30:47.352897 | 
2025-11-26 07:30:47.352973 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-26 07:30:47.453858 | controller | ok
2025-11-26 07:30:47.472981 | controller | included: /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-26 07:30:47.500240 | 
2025-11-26 07:30:47.500324 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-26 07:30:47.572592 | controller | skipping: Conditional result was False
2025-11-26 07:30:47.579310 | 
2025-11-26 07:30:47.582415 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-26 07:30:48.491818 | controller | changed
2025-11-26 07:30:48.499840 | 
2025-11-26 07:30:48.499930 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-26 07:30:48.838616 | controller | ok
2025-11-26 07:30:48.964308 | 
2025-11-26 07:30:48.964417 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-26 07:30:49.747374 | controller | changed
2025-11-26 07:30:49.762211 | 
2025-11-26 07:30:49.762282 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-26 07:30:50.547627 | controller | changed
2025-11-26 07:30:50.552825 | 
2025-11-26 07:30:50.552927 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-26 07:30:50.627623 | controller | skipping: Conditional result was False
2025-11-26 07:30:50.633952 | 
2025-11-26 07:30:50.634025 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-26 07:30:51.903959 | controller -> localhost | changed
2025-11-26 07:30:51.915195 | 
2025-11-26 07:30:51.915275 | TASK [add-build-sshkey : Add back temp key]
2025-11-26 07:30:52.941129 | controller -> localhost | Identity added: /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/04a778c41bbc4932ba83f3752f617298_id_rsa (zuul-build-sshkey)
2025-11-26 07:30:52.941297 | controller -> localhost | ok: Runtime: 0:00:00.025287
2025-11-26 07:30:52.947017 | 
2025-11-26 07:30:52.947079 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-26 07:30:53.876707 | controller | ok
2025-11-26 07:30:53.881577 | 
2025-11-26 07:30:53.881649 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-26 07:30:53.941336 | controller | skipping: Conditional result was False
2025-11-26 07:30:54.089670 | 
2025-11-26 07:30:54.089771 | TASK [include_role : validate-host]
2025-11-26 07:30:54.146195 | controller | ok
2025-11-26 07:30:54.210768 | 
2025-11-26 07:30:54.210867 | TASK [validate-host : Define zuul_info_dir fact]
2025-11-26 07:30:54.457357 | controller | ok
2025-11-26 07:30:54.466141 | 
2025-11-26 07:30:54.466223 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-11-26 07:30:55.053193 | controller -> localhost | ok
2025-11-26 07:30:55.060547 | 
2025-11-26 07:30:55.060613 | TASK [validate-host : Collect information about the host]
2025-11-26 07:30:55.721355 | controller | ok
2025-11-26 07:30:55.747527 | 
2025-11-26 07:30:55.747601 | TASK [validate-host : Sanitize hostname]
2025-11-26 07:30:56.014833 | controller | ok
2025-11-26 07:30:56.028755 | 
2025-11-26 07:30:56.028842 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-11-26 07:30:57.464081 | controller -> localhost | changed
2025-11-26 07:30:57.470051 | 
2025-11-26 07:30:57.470135 | TASK [validate-host : Collect information about zuul worker]
2025-11-26 07:30:58.605046 | controller | ok
2025-11-26 07:30:58.615966 | 
2025-11-26 07:30:58.616052 | TASK [validate-host : Write out all zuul information for each host]
2025-11-26 07:31:00.016245 | controller -> localhost | changed
2025-11-26 07:31:00.025616 | 
2025-11-26 07:31:00.025679 | TASK [include_role : prepare-workspace-openshift]
2025-11-26 07:31:00.098817 | controller | skipping: Conditional result was False
2025-11-26 07:31:00.104224 | 
2025-11-26 07:31:00.104288 | TASK [include_role : remove-zuul-sshkey]
2025-11-26 07:31:00.147500 | controller | skipping: Conditional result was False
2025-11-26 07:31:00.153115 | 
2025-11-26 07:31:00.153187 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-26 07:31:00.461338 | controller | ok: "logs"
2025-11-26 07:31:00.461571 | controller | ok: All items complete
2025-11-26 07:31:00.461604 | 
2025-11-26 07:31:00.658453 | controller | ok: "artifacts"
2025-11-26 07:31:00.844010 | controller | ok: "docs"
2025-11-26 07:31:00.851078 | 
2025-11-26 07:31:00.851180 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-26 07:31:01.183337 | controller | changed: "logs"
2025-11-26 07:31:01.358041 | controller | changed: "artifacts"
2025-11-26 07:31:01.543643 | controller | changed: "docs"
2025-11-26 07:31:01.641499 | 
2025-11-26 07:31:01.641591 | PLAY RECAP
2025-11-26 07:31:01.641639 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-11-26 07:31:01.641669 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-26 07:31:01.641690 | 
2025-11-26 07:31:02.050809 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-11-26 07:31:02.051673 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-11-26 07:31:04.329681 | 
2025-11-26 07:31:04.329795 | PLAY [all]
2025-11-26 07:31:04.409075 | 
2025-11-26 07:31:04.409188 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-11-26 07:31:04.536656 | controller | ok
2025-11-26 07:31:04.541715 | 
2025-11-26 07:31:04.541805 | TASK [mirror-info-fork : Create /etc/ci]
2025-11-26 07:31:05.300005 | controller | changed
2025-11-26 07:31:05.309359 | 
2025-11-26 07:31:05.311536 | TASK [mirror-info-fork : Install ci_mirror script]
2025-11-26 07:31:07.167754 | controller | changed
2025-11-26 07:31:07.217990 | 
2025-11-26 07:31:07.218098 | LOOP [add-authorized-keys : Enable access via build key on all nodes]
2025-11-26 07:31:08.013760 | controller | changed:
2025-11-26 07:31:08.013938 | controller | {
2025-11-26 07:31:08.013972 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com"
2025-11-26 07:31:08.014002 | controller | }
2025-11-26 07:31:08.228608 | controller | changed:
2025-11-26 07:31:08.228689 | controller | {
2025-11-26 07:31:08.228720 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com"
2025-11-26 07:31:08.228744 | controller | }
2025-11-26 07:31:08.464548 | controller | changed:
2025-11-26 07:31:08.464624 | controller | {
2025-11-26 07:31:08.464654 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com"
2025-11-26 07:31:08.464676 | controller | }
2025-11-26 07:31:08.682565 | controller | changed:
2025-11-26 07:31:08.682638 | controller | {
2025-11-26 07:31:08.682665 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com"
2025-11-26 07:31:08.682686 | controller | }
2025-11-26 07:31:08.925822 | controller | changed:
2025-11-26 07:31:08.925896 | controller | {
2025-11-26 07:31:08.925938 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com"
2025-11-26 07:31:08.925960 | controller | }
2025-11-26 07:31:09.164433 | controller | changed:
2025-11-26 07:31:09.164514 | controller | {
2025-11-26 07:31:09.164543 | controller |   "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com"
2025-11-26 07:31:09.164566 | controller | }
2025-11-26 07:31:09.387727 | controller | changed:
2025-11-26 07:31:09.387801 | controller | {
2025-11-26 07:31:09.387829 | 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-11-26 07:31:09.387852 | controller | }
2025-11-26 07:31:09.622148 | controller | changed:
2025-11-26 07:31:09.622237 | controller | {
2025-11-26 07:31:09.622266 | 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-11-26 07:31:09.622289 | controller | }
2025-11-26 07:31:09.907697 | controller | changed:
2025-11-26 07:31:09.907789 | controller | {
2025-11-26 07:31:09.907819 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner"
2025-11-26 07:31:09.907842 | controller | }
2025-11-26 07:31:10.100476 | controller | changed:
2025-11-26 07:31:10.100560 | controller | {
2025-11-26 07:31:10.100589 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com"
2025-11-26 07:31:10.100611 | controller | }
2025-11-26 07:31:10.335180 | controller | changed:
2025-11-26 07:31:10.335269 | controller | {
2025-11-26 07:31:10.335299 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com"
2025-11-26 07:31:10.335321 | controller | }
2025-11-26 07:31:10.586463 | controller | changed:
2025-11-26 07:31:10.586549 | controller | {
2025-11-26 07:31:10.586579 | controller |   "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com"
2025-11-26 07:31:10.586602 | controller | }
2025-11-26 07:31:10.803226 | controller | changed:
2025-11-26 07:31:10.803304 | controller | {
2025-11-26 07:31:10.803333 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith"
2025-11-26 07:31:10.803355 | controller | }
2025-11-26 07:31:11.024491 | controller | changed:
2025-11-26 07:31:11.024573 | controller | {
2025-11-26 07:31:11.024601 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel"
2025-11-26 07:31:11.024624 | controller | }
2025-11-26 07:31:11.275825 | controller | changed:
2025-11-26 07:31:11.276036 | controller | {
2025-11-26 07:31:11.276067 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux"
2025-11-26 07:31:11.276090 | controller | }
2025-11-26 07:31:11.529594 | controller | changed:
2025-11-26 07:31:11.529669 | controller | {
2025-11-26 07:31:11.529697 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr"
2025-11-26 07:31:11.529717 | controller | }
2025-11-26 07:31:11.793622 | controller | changed:
2025-11-26 07:31:11.793720 | controller | {
2025-11-26 07:31:11.793747 | 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-11-26 07:31:11.793768 | controller | }
2025-11-26 07:31:12.039522 | controller | changed:
2025-11-26 07:31:12.039613 | controller | {
2025-11-26 07:31:12.039641 | 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-11-26 07:31:12.039671 | controller | }
2025-11-26 07:31:12.310669 | controller | changed:
2025-11-26 07:31:12.310755 | controller | {
2025-11-26 07:31:12.310784 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9"
2025-11-26 07:31:12.310807 | controller | }
2025-11-26 07:31:12.587019 | controller | changed:
2025-11-26 07:31:12.587105 | controller | {
2025-11-26 07:31:12.587134 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora"
2025-11-26 07:31:12.587156 | controller | }
2025-11-26 07:31:12.843279 | controller | changed:
2025-11-26 07:31:12.843367 | controller | {
2025-11-26 07:31:12.843433 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac"
2025-11-26 07:31:12.843459 | controller | }
2025-11-26 07:31:13.106664 | controller | changed:
2025-11-26 07:31:13.106745 | controller | {
2025-11-26 07:31:13.106773 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop"
2025-11-26 07:31:13.106795 | controller | }
2025-11-26 07:31:13.355036 | controller | changed:
2025-11-26 07:31:13.355113 | controller | {
2025-11-26 07:31:13.355141 | 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-11-26 07:31:13.355163 | controller | }
2025-11-26 07:31:13.622557 | controller | changed:
2025-11-26 07:31:13.622637 | controller | {
2025-11-26 07:31:13.622666 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com"
2025-11-26 07:31:13.622688 | controller | }
2025-11-26 07:31:13.871893 | controller | changed:
2025-11-26 07:31:13.871983 | controller | {
2025-11-26 07:31:13.872011 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com"
2025-11-26 07:31:13.872032 | controller | }
2025-11-26 07:31:14.125658 | controller | changed:
2025-11-26 07:31:14.125752 | controller | {
2025-11-26 07:31:14.125781 | controller |   "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono"
2025-11-26 07:31:14.125803 | controller | }
2025-11-26 07:31:14.157523 | 
2025-11-26 07:31:14.157627 | TASK [Set timezone to UTC]
2025-11-26 07:31:15.383667 | controller | changed: executed `/bin/timedatectl set-timezone UTC`
2025-11-26 07:31:15.390444 | 
2025-11-26 07:31:15.390512 | TASK [Create nodepool directory]
2025-11-26 07:31:15.681049 | controller | changed
2025-11-26 07:31:15.691999 | 
2025-11-26 07:31:15.692081 | TASK [Create nodepool sub_nodes file]
2025-11-26 07:31:16.536941 | controller | changed
2025-11-26 07:31:16.542219 | 
2025-11-26 07:31:16.542305 | TASK [Create nodepool sub_nodes_private file]
2025-11-26 07:31:17.384883 | controller | changed
2025-11-26 07:31:17.397800 | 
2025-11-26 07:31:17.397884 | LOOP [Populate nodepool sub_nodes file]
2025-11-26 07:31:17.494773 | 
2025-11-26 07:31:17.494932 | LOOP [Populate nodepool sub_nodes_private file]
2025-11-26 07:31:17.631879 | 
2025-11-26 07:31:17.632037 | TASK [Create nodepool primary file]
2025-11-26 07:31:17.719279 | controller | skipping: Conditional result was False
2025-11-26 07:31:17.728630 | 
2025-11-26 07:31:17.728722 | TASK [Create nodepool node_private for this node]
2025-11-26 07:31:18.545735 | controller | changed
2025-11-26 07:31:18.558366 | 
2025-11-26 07:31:18.558471 | LOOP [Copy ssh keys to nodepool directory]
2025-11-26 07:31:19.521430 | controller | ok: Item: id_rsa Runtime: 0:00:00.005591
2025-11-26 07:31:19.521604 | 
2025-11-26 07:31:19.711116 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.005364
2025-11-26 07:31:19.725864 | 
2025-11-26 07:31:19.725973 | TASK [Add sudoers role for zuul-sudo-grep.sh]
2025-11-26 07:31:20.530343 | controller | changed
2025-11-26 07:31:20.539676 | 
2025-11-26 07:31:20.539743 | TASK [Validate sudoers config after edits]
2025-11-26 07:31:20.970805 | controller | /etc/sudoers: parsed OK
2025-11-26 07:31:20.970860 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK
2025-11-26 07:31:20.970869 | controller | /etc/sudoers.d/zuul: parsed OK
2025-11-26 07:31:20.970877 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK
2025-11-26 07:31:21.161033 | controller | ok: Runtime: 0:00:00.008564
2025-11-26 07:31:21.166600 | 
2025-11-26 07:31:21.166666 | TASK [Show the environment passed in to job shell scripts]
2025-11-26 07:31:21.588982 | controller | SHELL=/bin/bash
2025-11-26 07:31:21.589024 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework
2025-11-26 07:31:21.589033 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework
2025-11-26 07:31:21.589040 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/05/3505/48e1843efd45f40e0afe5b5c680514c004968226
2025-11-26 07:31:21.589046 | controller | PWD=/home/zuul
2025-11-26 07:31:21.589052 | controller | ZUUL_PIPELINE=github-check
2025-11-26 07:31:21.589057 | controller | LOGNAME=zuul
2025-11-26 07:31:21.589063 | controller | XDG_SESSION_TYPE=tty
2025-11-26 07:31:21.589068 | controller | _=/usr/bin/env
2025-11-26 07:31:21.589074 | controller | MOTD_SHOWN=pam
2025-11-26 07:31:21.589079 | controller | HOME=/home/zuul
2025-11-26 07:31:21.589118 | controller | LANG=en_US.UTF-8
2025-11-26 07:31:21.589125 | controller | SSH_CONNECTION=192.168.25.12 47240 192.168.25.53 22
2025-11-26 07:31:21.589131 | 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-11-26 07:31:21.589139 | controller | ZUUL_CHANGE_IDS=3505,48e1843efd45f40e0afe5b5c680514c004968226
2025-11-26 07:31:21.589145 | controller | WORKSPACE=/home/zuul/workspace
2025-11-26 07:31:21.589150 | controller | XDG_SESSION_CLASS=user
2025-11-26 07:31:21.589156 | controller | SELINUX_ROLE_REQUESTED=
2025-11-26 07:31:21.589161 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s
2025-11-26 07:31:21.589166 | controller | USER=zuul
2025-11-26 07:31:21.589172 | controller | ZUUL_VOTING=True
2025-11-26 07:31:21.589177 | controller | BUILD_TIMEOUT=1800000
2025-11-26 07:31:21.589182 | controller | SELINUX_USE_CURRENT_RANGE=
2025-11-26 07:31:21.589188 | controller | SHLVL=1
2025-11-26 07:31:21.589193 | controller | ZUUL_PATCHSET=48e1843efd45f40e0afe5b5c680514c004968226
2025-11-26 07:31:21.589199 | controller | XDG_SESSION_ID=1
2025-11-26 07:31:21.589204 | controller | ZUUL_BRANCH=main
2025-11-26 07:31:21.589209 | controller | XDG_RUNTIME_DIR=/run/user/1000
2025-11-26 07:31:21.589215 | controller | SSH_CLIENT=192.168.25.12 47240 22
2025-11-26 07:31:21.589221 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/
2025-11-26 07:31:21.589227 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima:
2025-11-26 07:31:21.589232 | controller | which_declare=declare -f
2025-11-26 07:31:21.589238 | controller | PATH=/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin
2025-11-26 07:31:21.589243 | controller | SELINUX_LEVEL_REQUESTED=
2025-11-26 07:31:21.589249 | controller | ZUUL_CHANGE=3505
2025-11-26 07:31:21.589254 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2025-11-26 07:31:21.589259 | controller | ZUUL_UUID=04a778c41bbc4932ba83f3752f617298
2025-11-26 07:31:21.589265 | controller | BASH_FUNC_which%%=() {  ( alias;
2025-11-26 07:31:21.589271 | controller |  eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@
2025-11-26 07:31:21.589276 | controller | }
2025-11-26 07:31:21.769111 | controller | ok: Runtime: 0:00:00.005962
2025-11-26 07:31:21.774781 | 
2025-11-26 07:31:21.774847 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars]
2025-11-26 07:31:21.849131 | controller | skipping: Conditional result was False
2025-11-26 07:31:21.854944 | 
2025-11-26 07:31:21.855030 | TASK [Symlink /home/zuul-worker/workspace]
2025-11-26 07:31:22.621754 | controller | skipping: Conditional result was False
2025-11-26 07:31:22.628408 | 
2025-11-26 07:31:22.628490 | TASK [Ensure legacy workspace directory]
2025-11-26 07:31:22.841512 | controller | changed
2025-11-26 07:31:22.903353 | 
2025-11-26 07:31:22.903487 | PLAY RECAP
2025-11-26 07:31:22.903541 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-11-26 07:31:22.903566 | 
2025-11-26 07:31:23.150032 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master]
2025-11-26 07:31:23.150779 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-11-26 07:31:24.468313 | 
2025-11-26 07:31:24.468441 | PLAY [Run ci/playbooks/dump_zuul_data.yml]
2025-11-26 07:31:24.553511 | 
2025-11-26 07:31:24.553608 | TASK [Create zuul-output directory]
2025-11-26 07:31:25.180233 | controller | changed
2025-11-26 07:31:25.188983 | 
2025-11-26 07:31:25.189071 | TASK [Slurp Zuul inventory test]
2025-11-26 07:31:26.217111 | controller -> localhost | ok
2025-11-26 07:31:26.224370 | 
2025-11-26 07:31:26.224468 | TASK [Save zuul inventory]
2025-11-26 07:31:27.828030 | controller | changed
2025-11-26 07:31:27.833026 | 
2025-11-26 07:31:27.833101 | TASK [Save zuul vars without the change_message]
2025-11-26 07:31:28.882605 | controller | changed
2025-11-26 07:31:28.945278 | 
2025-11-26 07:31:28.945363 | PLAY RECAP
2025-11-26 07:31:28.945433 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-26 07:31:28.945459 | 
2025-11-26 07:31:29.250319 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main]
2025-11-26 07:31:29.251185 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-11-26 07:31:31.259401 | 
2025-11-26 07:31:31.259521 | PLAY [Run ci/playbooks/molecule-prepare.yml]
2025-11-26 07:31:31.324414 | 
2025-11-26 07:31:31.324543 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh]
2025-11-26 07:31:31.374729 | controller | ok
2025-11-26 07:31:31.411827 | 
2025-11-26 07:31:31.411983 | TASK [mirror-info-fork : Set mirror_fqdn if not defined]
2025-11-26 07:31:31.466335 | controller | skipping: Conditional result was False
2025-11-26 07:31:31.472496 | 
2025-11-26 07:31:31.472582 | TASK [mirror-info-fork : Create /etc/ci]
2025-11-26 07:31:31.975082 | controller | ok
2025-11-26 07:31:31.983956 | 
2025-11-26 07:31:31.984046 | TASK [mirror-info-fork : Install ci_mirror script]
2025-11-26 07:31:32.781474 | controller | ok
2025-11-26 07:31:32.813175 | 
2025-11-26 07:31:32.813284 | TASK [Prepare workspace]
2025-11-26 07:31:32.858935 | controller | ok
2025-11-26 07:31:32.945766 | 
2025-11-26 07:31:32.945861 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-26 07:31:33.526609 | controller | ok
2025-11-26 07:31:33.559969 | 
2025-11-26 07:31:33.560092 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-26 07:31:37.710859 | controller | Output suppressed because no_log was given
2025-11-26 07:31:37.720120 | 
2025-11-26 07:31:37.720184 | LOOP [Create zuul-output directory]
2025-11-26 07:31:37.909813 | controller | changed: "/home/zuul/ci-framework-data/logs"
2025-11-26 07:31:38.065853 | controller | ok: "/home/zuul/zuul-output/logs"
2025-11-26 07:31:38.074430 | 
2025-11-26 07:31:38.074500 | TASK [Install required packages]
2025-11-26 07:32:33.728954 | controller | changed
2025-11-26 07:32:33.734221 | 
2025-11-26 07:32:33.734301 | TASK [Install venv]
2025-11-26 07:33:37.702864 | controller | changed
2025-11-26 07:33:37.728538 | 
2025-11-26 07:33:37.728621 | PLAY RECAP
2025-11-26 07:33:37.728663 | controller | ok: 7 changed: 4 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-11-26 07:33:37.728686 | 
2025-11-26 07:33:37.800309 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main]
2025-11-26 07:33:37.801173 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-11-26 07:33:38.352985 | 
2025-11-26 07:33:38.353104 | PLAY [Run ci/playbooks/molecule-test.yml]
2025-11-26 07:33:38.412348 | 
2025-11-26 07:33:38.412485 | TASK [Gather required facts]
2025-11-26 07:33:38.944187 | controller | ok
2025-11-26 07:33:38.949597 | 
2025-11-26 07:33:38.949700 | TASK [Load environment var if instructed to]
2025-11-26 07:33:38.973659 | controller | skipping: Conditional result was False
2025-11-26 07:33:38.979180 | 
2025-11-26 07:33:38.979268 | TASK [Ensure group_vars dir exists]
2025-11-26 07:33:39.300931 | controller | ok
2025-11-26 07:33:39.312857 | 
2025-11-26 07:33:39.312945 | TASK [Print related variables]
2025-11-26 07:33:39.340987 | controller | ok:
2025-11-26 07:33:39.341110 | controller | mol_config_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config_local.yml
2025-11-26 07:33:39.341139 | controller | roles_dir: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/nat64_appliance
2025-11-26 07:33:39.346300 | 
2025-11-26 07:33:39.346365 | TASK [Run molecule]
2025-11-26 07:33:40.302504 | controller | INFO     Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml
2025-11-26 07:33:40.372688 | controller | INFO     Performing prerun with role_name_check=0...
2025-11-26 07:33:59.774031 | 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-11-26 07:33:59.774448 | 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-11-26 07:33:59.774915 | 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-11-26 07:33:59.775384 | 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-11-26 07:33:59.775853 | controller | WARNING  Another version of 'cifmw.general' 1.0.0+69a40365 was found installed in /home/zuul/.cache/ansible-compat/1fc58a/collections/ansible_collections, only the first one will be used, 1.0.0+69a40365 (/home/zuul/.ansible/collections/ansible_collections).
2025-11-26 07:33:59.776317 | 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-11-26 07:33:59.776761 | 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-11-26 07:33:59.777228 | 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-11-26 07:33:59.777655 | 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-11-26 07:33:59.778097 | 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-11-26 07:33:59.778551 | 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-11-26 07:33:59.779020 | 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-11-26 07:33:59.779474 | 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-11-26 07:33:59.779915 | 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-11-26 07:33:59.780362 | 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-11-26 07:33:59.790025 | controller | INFO     Running default > prepare
2025-11-26 07:34:00.491575 | controller |
2025-11-26 07:34:00.491654 | controller | PLAY [Prepare] *****************************************************************
2025-11-26 07:34:00.491757 | controller |
2025-11-26 07:34:00.491886 | controller | TASK [Gathering Facts] *********************************************************
2025-11-26 07:34:00.491988 | controller | Wednesday 26 November 2025  07:34:00 +0000 (0:00:00.020)       0:00:00.020 ****
2025-11-26 07:34:01.308396 | controller | ok: [instance]
2025-11-26 07:34:01.308467 | controller |
2025-11-26 07:34:01.308577 | controller | TASK [Create custom basedir] ***************************************************
2025-11-26 07:34:01.308683 | controller | Wednesday 26 November 2025  07:34:01 +0000 (0:00:00.817)       0:00:00.838 ****
2025-11-26 07:34:01.605635 | controller | ok: [instance]
2025-11-26 07:34:01.605708 | controller |
2025-11-26 07:34:01.605841 | controller | TASK [Install some debug utils] ************************************************
2025-11-26 07:34:01.605955 | controller | Wednesday 26 November 2025  07:34:01 +0000 (0:00:00.297)       0:00:01.135 ****
2025-11-26 07:34:05.861160 | controller | changed: [instance]
2025-11-26 07:34:05.861246 | controller |
2025-11-26 07:34:05.861368 | controller | TASK [test_deps : Gather facts if they don't exist] ****************************
2025-11-26 07:34:05.861486 | controller | Wednesday 26 November 2025  07:34:05 +0000 (0:00:04.254)       0:00:05.389 ****
2025-11-26 07:34:05.881089 | controller | skipping: [instance]
2025-11-26 07:34:05.881206 | controller |
2025-11-26 07:34:05.881324 | controller | TASK [test_deps : Gather variables for each operating system] ******************
2025-11-26 07:34:05.881442 | controller | Wednesday 26 November 2025  07:34:05 +0000 (0:00:00.020)       0:00:05.410 ****
2025-11-26 07:34:05.927100 | controller | ok: [instance] => (item=/home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/test_deps/vars/centos-9.yml)
2025-11-26 07:34:05.927210 | controller |
2025-11-26 07:34:05.927339 | controller | TASK [test_deps : Detect mirrors file] *****************************************
2025-11-26 07:34:05.927449 | controller | Wednesday 26 November 2025  07:34:05 +0000 (0:00:00.045)       0:00:05.456 ****
2025-11-26 07:34:06.242012 | controller | ok: [instance]
2025-11-26 07:34:06.242069 | controller |
2025-11-26 07:34:06.242278 | controller | TASK [test_deps : Disable ubi host subscription-manager integration] ***********
2025-11-26 07:34:06.242403 | controller | Wednesday 26 November 2025  07:34:06 +0000 (0:00:00.314)       0:00:05.771 ****
2025-11-26 07:34:06.495817 | controller | ok: [instance]
2025-11-26 07:34:06.495886 | controller |
2025-11-26 07:34:06.496012 | controller | TASK [test_deps : Disable ubi 9 repos] *****************************************
2025-11-26 07:34:06.496135 | controller | Wednesday 26 November 2025  07:34:06 +0000 (0:00:00.253)       0:00:06.024 ****
2025-11-26 07:34:07.249653 | controller | ok: [instance] => (item=ubi-9-appstream)
2025-11-26 07:34:07.249713 | controller | ok: [instance] => (item=ubi-9-baseos)
2025-11-26 07:34:07.250298 | controller | ok: [instance] => (item=ubi-9-codeready-builder)
2025-11-26 07:34:07.312154 | controller |
2025-11-26 07:34:07.312213 | controller | TASK [Deploy repo-setup] *******************************************************
2025-11-26 07:34:07.312223 | controller | Wednesday 26 November 2025  07:34:07 +0000 (0:00:00.754)       0:00:06.778 ****
2025-11-26 07:34:07.312235 | controller |
2025-11-26 07:34:07.880906 | controller | TASK [repo_setup : Ensure directories are present] *****************************
2025-11-26 07:34:07.880953 | controller | Wednesday 26 November 2025  07:34:07 +0000 (0:00:00.062)       0:00:06.841 ****
2025-11-26 07:34:07.880976 | controller | changed: [instance] => (item=tmp)
2025-11-26 07:34:07.880995 | controller | changed: [instance] => (item=artifacts/repositories)
2025-11-26 07:34:07.881004 | controller | changed: [instance] => (item=venv/repo_setup)
2025-11-26 07:34:07.881388 | controller |
2025-11-26 07:34:08.551236 | controller | TASK [repo_setup : Make sure git-core package is installed] ********************
2025-11-26 07:34:08.551268 | controller | Wednesday 26 November 2025  07:34:07 +0000 (0:00:00.569)       0:00:07.410 ****
2025-11-26 07:34:08.551279 | controller | ok: [instance]
2025-11-26 07:34:09.633280 | controller |
2025-11-26 07:34:09.633316 | controller | TASK [repo_setup : Get repo-setup repository] **********************************
2025-11-26 07:34:09.633325 | controller | Wednesday 26 November 2025  07:34:08 +0000 (0:00:00.670)       0:00:08.080 ****
2025-11-26 07:34:09.633335 | controller | changed: [instance]
2025-11-26 07:34:17.538577 | controller |
2025-11-26 07:34:17.538609 | controller | TASK [repo_setup : Initialize python venv and install requirements] ************
2025-11-26 07:34:17.538618 | controller | Wednesday 26 November 2025  07:34:09 +0000 (0:00:01.082)       0:00:09.162 ****
2025-11-26 07:34:17.538628 | controller | changed: [instance]
2025-11-26 07:34:18.285317 | controller |
2025-11-26 07:34:18.285352 | controller | TASK [repo_setup : Install repo-setup package] *********************************
2025-11-26 07:34:18.285360 | controller | Wednesday 26 November 2025  07:34:17 +0000 (0:00:07.905)       0:00:17.068 ****
2025-11-26 07:34:18.285371 | controller | changed: [instance]
2025-11-26 07:34:18.308213 | controller |
2025-11-26 07:34:18.308236 | controller | TASK [repo_setup : Set cifmw_repo_setup_dlrn_hash_tag from content provider] ***
2025-11-26 07:34:18.308256 | controller | Wednesday 26 November 2025  07:34:18 +0000 (0:00:00.746)       0:00:17.814 ****
2025-11-26 07:34:18.308266 | controller | skipping: [instance]
2025-11-26 07:34:19.122891 | controller |
2025-11-26 07:34:19.122922 | controller | TASK [repo_setup : Run repo-setup] *********************************************
2025-11-26 07:34:19.122931 | controller | Wednesday 26 November 2025  07:34:18 +0000 (0:00:00.023)       0:00:17.838 ****
2025-11-26 07:34:19.122942 | controller | changed: [instance]
2025-11-26 07:34:19.123295 | controller |
2025-11-26 07:34:19.123323 | controller | TASK [repo_setup : Get component repo] *****************************************
2025-11-26 07:34:19.123335 | controller | Wednesday 26 November 2025  07:34:19 +0000 (0:00:00.814)       0:00:18.652 ****
2025-11-26 07:34:19.191793 | controller | skipping: [instance]
2025-11-26 07:34:19.228664 | controller |
2025-11-26 07:34:19.228687 | controller | TASK [repo_setup : Rename component repo] **************************************
2025-11-26 07:34:19.228696 | controller | Wednesday 26 November 2025  07:34:19 +0000 (0:00:00.069)       0:00:18.721 ****
2025-11-26 07:34:19.228705 | controller | skipping: [instance]
2025-11-26 07:34:19.264823 | controller |
2025-11-26 07:34:19.264844 | controller | TASK [repo_setup : Disable component repo in current-podified dlrn repo] *******
2025-11-26 07:34:19.264851 | controller | Wednesday 26 November 2025  07:34:19 +0000 (0:00:00.036)       0:00:18.758 ****
2025-11-26 07:34:19.264860 | controller | skipping: [instance]
2025-11-26 07:34:19.808277 | controller |
2025-11-26 07:34:19.808311 | controller | TASK [repo_setup : Run repo-setup-get-hash] ************************************
2025-11-26 07:34:19.808319 | controller | Wednesday 26 November 2025  07:34:19 +0000 (0:00:00.036)       0:00:18.794 ****
2025-11-26 07:34:19.808329 | controller | changed: [instance]
2025-11-26 07:34:20.236696 | controller |
2025-11-26 07:34:20.236726 | controller | TASK [repo_setup : Dump full hash in delorean.repo.md5 file] *******************
2025-11-26 07:34:20.236735 | controller | Wednesday 26 November 2025  07:34:19 +0000 (0:00:00.543)       0:00:19.337 ****
2025-11-26 07:34:20.236749 | controller | changed: [instance]
2025-11-26 07:34:20.265705 | controller |
2025-11-26 07:34:20.265725 | controller | TASK [repo_setup : Dump current-podified hash] *********************************
2025-11-26 07:34:20.265733 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.428)       0:00:19.766 ****
2025-11-26 07:34:20.265742 | controller | skipping: [instance]
2025-11-26 07:34:20.294907 | controller |
2025-11-26 07:34:20.294940 | controller | TASK [repo_setup : Slurp current podified hash] ********************************
2025-11-26 07:34:20.294949 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.029)       0:00:19.795 ****
2025-11-26 07:34:20.294959 | controller | skipping: [instance]
2025-11-26 07:34:20.294985 | controller |
2025-11-26 07:34:20.295214 | controller | TASK [repo_setup : Update the value of full_hash] ******************************
2025-11-26 07:34:20.323857 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.029)       0:00:19.824 ****
2025-11-26 07:34:20.323895 | controller | skipping: [instance]
2025-11-26 07:34:20.361877 | controller |
2025-11-26 07:34:20.361909 | controller | TASK [repo_setup : Export hashes facts for further use] ************************
2025-11-26 07:34:20.361917 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.028)       0:00:19.853 ****
2025-11-26 07:34:20.361936 | controller | ok: [instance]
2025-11-26 07:34:20.388721 | controller |
2025-11-26 07:34:20.388753 | controller | TASK [repo_setup : Create download directory] **********************************
2025-11-26 07:34:20.388761 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.037)       0:00:19.891 ****
2025-11-26 07:34:20.388772 | controller | skipping: [instance]
2025-11-26 07:34:20.388896 | controller |
2025-11-26 07:34:20.389033 | controller | TASK [repo_setup : Print the URL to request] ***********************************
2025-11-26 07:34:20.389158 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.027)       0:00:19.918 ****
2025-11-26 07:34:20.416101 | controller | skipping: [instance]
2025-11-26 07:34:20.416225 | controller |
2025-11-26 07:34:20.416367 | controller | TASK [Download the RPM] ********************************************************
2025-11-26 07:34:20.416503 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.027)       0:00:19.946 ****
2025-11-26 07:34:20.444204 | controller | skipping: [instance]
2025-11-26 07:34:20.444369 | controller |
2025-11-26 07:34:20.444519 | controller | TASK [repo_setup : Install RHOS Release tool] **********************************
2025-11-26 07:34:20.444668 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.028)       0:00:19.974 ****
2025-11-26 07:34:20.471591 | controller | skipping: [instance]
2025-11-26 07:34:20.471701 | controller |
2025-11-26 07:34:20.471842 | controller | TASK [repo_setup : Get rhos-release tool version] ******************************
2025-11-26 07:34:20.471976 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.027)       0:00:20.001 ****
2025-11-26 07:34:20.498063 | controller | skipping: [instance]
2025-11-26 07:34:20.498195 | controller |
2025-11-26 07:34:20.498367 | controller | TASK [repo_setup : Print rhos-release tool version] ****************************
2025-11-26 07:34:20.498517 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.026)       0:00:20.028 ****
2025-11-26 07:34:20.527167 | controller | skipping: [instance]
2025-11-26 07:34:20.527277 | controller |
2025-11-26 07:34:20.527418 | controller | TASK [repo_setup : Generate repos using rhos-release {{ cifmw_repo_setup_rhos_release_args }}] ***
2025-11-26 07:34:20.527539 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.028)       0:00:20.057 ****
2025-11-26 07:34:20.554109 | controller | skipping: [instance]
2025-11-26 07:34:20.554256 | controller |
2025-11-26 07:34:20.554400 | controller | TASK [repo_setup : Check for /etc/ci/mirror_info.sh] ***************************
2025-11-26 07:34:20.554523 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.027)       0:00:20.084 ****
2025-11-26 07:34:20.737228 | controller | ok: [instance]
2025-11-26 07:34:20.954345 | controller |
2025-11-26 07:34:20.954375 | controller | TASK [repo_setup : Use RDO proxy mirrors] **************************************
2025-11-26 07:34:20.954383 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.182)       0:00:20.266 ****
2025-11-26 07:34:20.954393 | controller | changed: [instance]
2025-11-26 07:34:21.180250 | controller |
2025-11-26 07:34:21.180297 | controller | TASK [repo_setup : Use RDO CentOS mirrors (remove CentOS 10 conditional when Nodepool mirrors exist)] ***
2025-11-26 07:34:21.180305 | controller | Wednesday 26 November 2025  07:34:20 +0000 (0:00:00.217)       0:00:20.483 ****
2025-11-26 07:34:21.180316 | controller | changed: [instance]
2025-11-26 07:34:21.200855 | controller |
2025-11-26 07:34:21.200886 | controller | TASK [repo_setup : Check for gating.repo file on content provider] *************
2025-11-26 07:34:21.200894 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.225)       0:00:20.709 ****
2025-11-26 07:34:21.200904 | controller | skipping: [instance]
2025-11-26 07:34:21.200929 | controller |
2025-11-26 07:34:21.201177 | controller | TASK [repo_setup : Populate gating repo from content provider ip] **************
2025-11-26 07:34:21.222366 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.021)       0:00:20.730 ****
2025-11-26 07:34:21.222408 | controller | skipping: [instance]
2025-11-26 07:34:21.244397 | controller |
2025-11-26 07:34:21.244424 | controller | TASK [repo_setup : Check for DLRN repo at the destination] *********************
2025-11-26 07:34:21.244434 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.021)       0:00:20.752 ****
2025-11-26 07:34:21.244445 | controller | skipping: [instance]
2025-11-26 07:34:21.266860 | controller |
2025-11-26 07:34:21.266893 | controller | TASK [repo_setup : Lower the priority of DLRN repos to allow installation from gating repo] ***
2025-11-26 07:34:21.266909 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.021)       0:00:20.774 ****
2025-11-26 07:34:21.266920 | controller | skipping: [instance]
2025-11-26 07:34:21.266944 | controller |
2025-11-26 07:34:21.266953 | controller | TASK [repo_setup : Check for DLRN component repo] ******************************
2025-11-26 07:34:21.267115 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.022)       0:00:20.796 ****
2025-11-26 07:34:21.288052 | controller | skipping: [instance]
2025-11-26 07:34:21.288207 | controller |
2025-11-26 07:34:21.288388 | controller | TASK [repo_setup : Lower the priority of componennt repos to allow installation from gating repo] ***
2025-11-26 07:34:21.288539 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.021)       0:00:20.818 ****
2025-11-26 07:34:21.309351 | controller | skipping: [instance]
2025-11-26 07:34:21.309506 | controller |
2025-11-26 07:34:21.309663 | controller | TASK [repo_setup : Find existing repos from /etc/yum.repos.d directory] ********
2025-11-26 07:34:21.309789 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.021)       0:00:20.839 ****
2025-11-26 07:34:21.325436 | controller | skipping: [instance]
2025-11-26 07:34:21.325584 | controller |
2025-11-26 07:34:21.325724 | controller | TASK [repo_setup : Remove existing repos from /etc/yum.repos.d directory] ******
2025-11-26 07:34:21.325866 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.016)       0:00:20.855 ****
2025-11-26 07:34:21.355244 | controller | skipping: [instance]
2025-11-26 07:34:21.355422 | controller |
2025-11-26 07:34:21.355570 | controller | TASK [repo_setup : Cleanup existing metadata] **********************************
2025-11-26 07:34:21.355715 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.029)       0:00:20.885 ****
2025-11-26 07:34:21.373898 | controller | skipping: [instance]
2025-11-26 07:34:21.374049 | controller |
2025-11-26 07:34:21.374200 | controller | TASK [repo_setup : Copy generated repos to /etc/yum.repos.d directory] *********
2025-11-26 07:34:21.374361 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.018)       0:00:20.904 ****
2025-11-26 07:34:21.394083 | controller | skipping: [instance]
2025-11-26 07:34:21.394233 | controller |
2025-11-26 07:34:21.394399 | controller | TASK [test_deps : Look for redhat-release rpm] *********************************
2025-11-26 07:34:21.394544 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.020)       0:00:20.924 ****
2025-11-26 07:34:21.422197 | controller | skipping: [instance]
2025-11-26 07:34:21.422370 | controller |
2025-11-26 07:34:21.422524 | controller | TASK [test_deps : Remove redhat-release] ***************************************
2025-11-26 07:34:21.422670 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.028)       0:00:20.952 ****
2025-11-26 07:34:21.450843 | controller | skipping: [instance]
2025-11-26 07:34:21.450989 | controller |
2025-11-26 07:34:21.451111 | controller | TASK [test_deps : Install centos-stream-release] *******************************
2025-11-26 07:34:21.451228 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.028)       0:00:20.980 ****
2025-11-26 07:34:21.480054 | controller | skipping: [instance]
2025-11-26 07:34:21.480209 | controller |
2025-11-26 07:34:21.480382 | controller | TASK [test_deps : Install additional packages] *********************************
2025-11-26 07:34:21.480531 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.029)       0:00:21.010 ****
2025-11-26 07:34:21.509583 | controller | skipping: [instance]
2025-11-26 07:34:21.509736 | controller |
2025-11-26 07:34:21.509912 | controller | TASK [test_deps : Install selinux python libs] *********************************
2025-11-26 07:34:21.510062 | controller | Wednesday 26 November 2025  07:34:21 +0000 (0:00:00.029)       0:00:21.039 ****
2025-11-26 07:35:09.154255 | controller | ok: [instance]
2025-11-26 07:35:10.383813 | controller |
2025-11-26 07:35:10.383844 | controller | TASK [test_deps : Install python yaml libs] ************************************
2025-11-26 07:35:10.383853 | controller | Wednesday 26 November 2025  07:35:09 +0000 (0:00:47.642)       0:01:08.682 ****
2025-11-26 07:35:10.383863 | controller | ok: [instance]
2025-11-26 07:35:10.415292 | controller |
2025-11-26 07:35:10.415321 | controller | TASK [test_deps : Install extra packages] **************************************
2025-11-26 07:35:10.415331 | controller | Wednesday 26 November 2025  07:35:10 +0000 (0:00:01.231)       0:01:09.913 ****
2025-11-26 07:35:10.415343 | controller | skipping: [instance]
2025-11-26 07:35:10.606824 | controller |
2025-11-26 07:35:10.606856 | controller | TASK [libvirt_manager : Ensure output directory exists] ************************
2025-11-26 07:35:10.606865 | controller | Wednesday 26 November 2025  07:35:10 +0000 (0:00:00.031)       0:01:09.945 ****
2025-11-26 07:35:10.606875 | controller | ok: [instance]
2025-11-26 07:35:10.791084 | controller |
2025-11-26 07:35:10.791115 | controller | TASK [libvirt_manager : Get vmx/svm extensions from /proc/cpuinfo] *************
2025-11-26 07:35:10.791128 | controller | Wednesday 26 November 2025  07:35:10 +0000 (0:00:00.191)       0:01:10.136 ****
2025-11-26 07:35:10.791139 | controller | changed: [instance]
2025-11-26 07:35:10.977159 | controller |
2025-11-26 07:35:10.977190 | controller | TASK [libvirt_manager : Check if KVM is enabled] *******************************
2025-11-26 07:35:10.977198 | controller | Wednesday 26 November 2025  07:35:10 +0000 (0:00:00.184)       0:01:10.320 ****
2025-11-26 07:35:10.977209 | controller | ok: [instance]
2025-11-26 07:35:11.005287 | controller |
2025-11-26 07:35:11.005318 | controller | TASK [libvirt_manager : Fail if KVM not enabled] *******************************
2025-11-26 07:35:11.005326 | controller | Wednesday 26 November 2025  07:35:10 +0000 (0:00:00.185)       0:01:10.506 ****
2025-11-26 07:35:11.005336 | controller | skipping: [instance]
2025-11-26 07:35:11.021570 | controller |
2025-11-26 07:35:11.021594 | controller | TASK [libvirt_manager : Check if VMX virtualization] ***************************
2025-11-26 07:35:11.021603 | controller | Wednesday 26 November 2025  07:35:11 +0000 (0:00:00.028)       0:01:10.534 ****
2025-11-26 07:35:11.021615 | controller | skipping: [instance]
2025-11-26 07:35:11.040860 | controller |
2025-11-26 07:35:11.040894 | controller | TASK [libvirt_manager : Check if SVM virtualization] ***************************
2025-11-26 07:35:11.040902 | controller | Wednesday 26 November 2025  07:35:11 +0000 (0:00:00.016)       0:01:10.551 ****
2025-11-26 07:35:11.040913 | controller | ok: [instance]
2025-11-26 07:35:11.040937 | controller |
2025-11-26 07:35:11.040945 | controller | TASK [libvirt_manager : Enable VMX virtualization] *****************************
2025-11-26 07:35:11.041022 | controller | Wednesday 26 November 2025  07:35:11 +0000 (0:00:00.019)       0:01:10.570 ****
2025-11-26 07:35:11.066291 | controller | skipping: [instance]
2025-11-26 07:36:45.162212 | controller |
2025-11-26 07:36:45.162245 | controller | TASK [libvirt_manager : Install packages required for using KVM] ***************
2025-11-26 07:36:45.162253 | controller | Wednesday 26 November 2025  07:35:11 +0000 (0:00:00.025)       0:01:10.596 ****
2025-11-26 07:36:45.162264 | controller | changed: [instance]
2025-11-26 07:36:45.374431 | controller |
2025-11-26 07:36:45.374471 | controller | TASK [libvirt_manager : Create rules.d polkit folder] **************************
2025-11-26 07:36:45.374480 | controller | Wednesday 26 November 2025  07:36:45 +0000 (0:01:34.095)       0:02:44.691 ****
2025-11-26 07:36:45.374491 | controller | changed: [instance]
2025-11-26 07:36:45.756574 | controller |
2025-11-26 07:36:45.756604 | controller | TASK [libvirt_manager : Enable UNIX socket PolicyKit auth] *********************
2025-11-26 07:36:45.756612 | controller | Wednesday 26 November 2025  07:36:45 +0000 (0:00:00.212)       0:02:44.904 ****
2025-11-26 07:36:45.756622 | controller | changed: [instance]
2025-11-26 07:36:46.384904 | controller |
2025-11-26 07:36:46.384933 | controller | TASK [libvirt_manager : Restart service polkit service] ************************
2025-11-26 07:36:46.384942 | controller | Wednesday 26 November 2025  07:36:45 +0000 (0:00:00.382)       0:02:45.286 ****
2025-11-26 07:36:46.384952 | controller | changed: [instance]
2025-11-26 07:36:46.580913 | controller |
2025-11-26 07:36:46.580943 | controller | TASK [libvirt_manager : Remove directory for service override] *****************
2025-11-26 07:36:46.580951 | controller | Wednesday 26 November 2025  07:36:46 +0000 (0:00:00.628)       0:02:45.914 ****
2025-11-26 07:36:46.580961 | controller | ok: [instance]
2025-11-26 07:36:47.287623 | controller |
2025-11-26 07:36:47.287651 | controller | TASK [libvirt_manager : Reload systemctl and start/enable virtproxyd.service] ***
2025-11-26 07:36:47.287659 | controller | Wednesday 26 November 2025  07:36:46 +0000 (0:00:00.195)       0:02:46.110 ****
2025-11-26 07:36:47.287670 | controller | ok: [instance]
2025-11-26 07:36:47.287704 | controller |
2025-11-26 07:36:47.287984 | controller | TASK [libvirt_manager : Ensure firewalld service is up] ************************
2025-11-26 07:36:48.109154 | controller | Wednesday 26 November 2025  07:36:47 +0000 (0:00:00.707)       0:02:46.817 ****
2025-11-26 07:36:48.109193 | controller | changed: [instance]
2025-11-26 07:36:48.183851 | controller |
2025-11-26 07:36:48.183876 | controller | TASK [libvirt_manager : Ensure libvirt modular driver daemons are started.] ****
2025-11-26 07:36:48.183884 | controller | Wednesday 26 November 2025  07:36:48 +0000 (0:00:00.821)       0:02:47.638 ****
2025-11-26 07:36:48.183894 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=qemu)
2025-11-26 07:36:48.183919 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=interface)
2025-11-26 07:36:48.184038 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=network)
2025-11-26 07:36:48.184151 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nodedev)
2025-11-26 07:36:48.184267 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=nwfilter)
2025-11-26 07:36:48.184388 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=secret)
2025-11-26 07:36:48.184496 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=storage)
2025-11-26 07:36:48.184602 | controller | included: /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/roles/libvirt_manager/tasks/drivers.yml for instance => (item=proxy)
2025-11-26 07:36:48.184696 | controller |
2025-11-26 07:36:48.184824 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for qemu.] *********
2025-11-26 07:36:48.184929 | controller | Wednesday 26 November 2025  07:36:48 +0000 (0:00:00.075)       0:02:47.713 ****
2025-11-26 07:36:48.513606 | controller | changed: [instance]
2025-11-26 07:36:48.839657 | controller |
2025-11-26 07:36:48.839686 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for qemu.] **********
2025-11-26 07:36:48.839694 | controller | Wednesday 26 November 2025  07:36:48 +0000 (0:00:00.329)       0:02:48.043 ****
2025-11-26 07:36:48.839710 | controller | changed: [instance]
2025-11-26 07:36:49.168099 | controller |
2025-11-26 07:36:49.168129 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for qemu.] **************
2025-11-26 07:36:49.168138 | controller | Wednesday 26 November 2025  07:36:48 +0000 (0:00:00.326)       0:02:48.369 ****
2025-11-26 07:36:49.168149 | controller | changed: [instance]
2025-11-26 07:36:49.499402 | controller |
2025-11-26 07:36:49.499431 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for interface.] ****
2025-11-26 07:36:49.499439 | controller | Wednesday 26 November 2025  07:36:49 +0000 (0:00:00.328)       0:02:48.697 ****
2025-11-26 07:36:49.499449 | controller | changed: [instance]
2025-11-26 07:36:49.822441 | controller |
2025-11-26 07:36:49.822470 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for interface.] *****
2025-11-26 07:36:49.822478 | controller | Wednesday 26 November 2025  07:36:49 +0000 (0:00:00.331)       0:02:49.029 ****
2025-11-26 07:36:49.822489 | controller | changed: [instance]
2025-11-26 07:36:50.140852 | controller |
2025-11-26 07:36:50.140881 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for interface.] *********
2025-11-26 07:36:50.140889 | controller | Wednesday 26 November 2025  07:36:49 +0000 (0:00:00.323)       0:02:49.352 ****
2025-11-26 07:36:50.140899 | controller | changed: [instance]
2025-11-26 07:36:50.141067 | controller |
2025-11-26 07:36:50.141346 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for network.] ******
2025-11-26 07:36:50.459907 | controller | Wednesday 26 November 2025  07:36:50 +0000 (0:00:00.318)       0:02:49.670 ****
2025-11-26 07:36:50.459941 | controller | changed: [instance]
2025-11-26 07:36:50.777859 | controller |
2025-11-26 07:36:50.777889 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for network.] *******
2025-11-26 07:36:50.777898 | controller | Wednesday 26 November 2025  07:36:50 +0000 (0:00:00.318)       0:02:49.989 ****
2025-11-26 07:36:50.777908 | controller | changed: [instance]
2025-11-26 07:36:51.102148 | controller |
2025-11-26 07:36:51.102186 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for network.] ***********
2025-11-26 07:36:51.102195 | controller | Wednesday 26 November 2025  07:36:50 +0000 (0:00:00.317)       0:02:50.307 ****
2025-11-26 07:36:51.102205 | controller | changed: [instance]
2025-11-26 07:36:51.427551 | controller |
2025-11-26 07:36:51.427582 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nodedev.] ******
2025-11-26 07:36:51.427590 | controller | Wednesday 26 November 2025  07:36:51 +0000 (0:00:00.324)       0:02:50.631 ****
2025-11-26 07:36:51.427601 | controller | changed: [instance]
2025-11-26 07:36:51.762912 | controller |
2025-11-26 07:36:51.762945 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nodedev.] *******
2025-11-26 07:36:51.762953 | controller | Wednesday 26 November 2025  07:36:51 +0000 (0:00:00.325)       0:02:50.957 ****
2025-11-26 07:36:51.762964 | controller | changed: [instance]
2025-11-26 07:36:51.763155 | controller |
2025-11-26 07:36:51.763190 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nodedev.] ***********
2025-11-26 07:36:52.100286 | controller | Wednesday 26 November 2025  07:36:51 +0000 (0:00:00.335)       0:02:51.292 ****
2025-11-26 07:36:52.100328 | controller | changed: [instance]
2025-11-26 07:36:52.428865 | controller |
2025-11-26 07:36:52.428896 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for nwfilter.] *****
2025-11-26 07:36:52.428904 | controller | Wednesday 26 November 2025  07:36:52 +0000 (0:00:00.337)       0:02:51.629 ****
2025-11-26 07:36:52.428915 | controller | changed: [instance]
2025-11-26 07:36:52.765559 | controller |
2025-11-26 07:36:52.765590 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for nwfilter.] ******
2025-11-26 07:36:52.765599 | controller | Wednesday 26 November 2025  07:36:52 +0000 (0:00:00.328)       0:02:51.958 ****
2025-11-26 07:36:52.765609 | controller | changed: [instance]
2025-11-26 07:36:53.108859 | controller |
2025-11-26 07:36:53.108899 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for nwfilter.] **********
2025-11-26 07:36:53.108908 | controller | Wednesday 26 November 2025  07:36:52 +0000 (0:00:00.336)       0:02:52.295 ****
2025-11-26 07:36:53.108919 | controller | changed: [instance]
2025-11-26 07:36:53.108939 | controller |
2025-11-26 07:36:53.109150 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for secret.] *******
2025-11-26 07:36:53.437337 | controller | Wednesday 26 November 2025  07:36:53 +0000 (0:00:00.343)       0:02:52.638 ****
2025-11-26 07:36:53.437370 | controller | changed: [instance]
2025-11-26 07:36:53.781276 | controller |
2025-11-26 07:36:53.781307 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for secret.] ********
2025-11-26 07:36:53.781315 | controller | Wednesday 26 November 2025  07:36:53 +0000 (0:00:00.328)       0:02:52.967 ****
2025-11-26 07:36:53.781325 | controller | changed: [instance]
2025-11-26 07:36:54.109067 | controller |
2025-11-26 07:36:54.109097 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for secret.] ************
2025-11-26 07:36:54.109111 | controller | Wednesday 26 November 2025  07:36:53 +0000 (0:00:00.343)       0:02:53.310 ****
2025-11-26 07:36:54.109121 | controller | changed: [instance]
2025-11-26 07:36:54.446920 | controller |
2025-11-26 07:36:54.446950 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for storage.] ******
2025-11-26 07:36:54.446959 | controller | Wednesday 26 November 2025  07:36:54 +0000 (0:00:00.327)       0:02:53.638 ****
2025-11-26 07:36:54.446968 | controller | changed: [instance]
2025-11-26 07:36:54.781575 | controller |
2025-11-26 07:36:54.781604 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for storage.] *******
2025-11-26 07:36:54.781612 | controller | Wednesday 26 November 2025  07:36:54 +0000 (0:00:00.337)       0:02:53.976 ****
2025-11-26 07:36:54.781622 | controller | changed: [instance]
2025-11-26 07:36:55.109328 | controller |
2025-11-26 07:36:55.109357 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for storage.] ***********
2025-11-26 07:36:55.109366 | controller | Wednesday 26 November 2025  07:36:54 +0000 (0:00:00.334)       0:02:54.311 ****
2025-11-26 07:36:55.109376 | controller | changed: [instance]
2025-11-26 07:36:55.434612 | controller |
2025-11-26 07:36:55.434642 | controller | TASK [libvirt_manager : Ensure read-write socket is enabled for proxy.] ********
2025-11-26 07:36:55.434650 | controller | Wednesday 26 November 2025  07:36:55 +0000 (0:00:00.327)       0:02:54.639 ****
2025-11-26 07:36:55.434667 | controller | changed: [instance]
2025-11-26 07:36:55.781911 | controller |
2025-11-26 07:36:55.781942 | controller | TASK [libvirt_manager : Ensure read-only socket is enabled for proxy.] *********
2025-11-26 07:36:55.781951 | controller | Wednesday 26 November 2025  07:36:55 +0000 (0:00:00.325)       0:02:54.964 ****
2025-11-26 07:36:55.781961 | controller | changed: [instance]
2025-11-26 07:36:56.117411 | controller |
2025-11-26 07:36:56.117440 | controller | TASK [libvirt_manager : Ensure admin socket is enabled for proxy.] *************
2025-11-26 07:36:56.117448 | controller | Wednesday 26 November 2025  07:36:55 +0000 (0:00:00.347)       0:02:55.311 ****
2025-11-26 07:36:56.117458 | controller | changed: [instance]
2025-11-26 07:36:56.135890 | controller |
2025-11-26 07:36:56.135933 | controller | TASK [libvirt_manager : Manage service for older releases] *********************
2025-11-26 07:36:56.135943 | controller | Wednesday 26 November 2025  07:36:56 +0000 (0:00:00.335)       0:02:55.647 ****
2025-11-26 07:36:56.135956 | controller | skipping: [instance]
2025-11-26 07:36:56.135980 | controller |
2025-11-26 07:36:56.136191 | controller | TASK [libvirt_manager : Get libvirt group users] *******************************
2025-11-26 07:36:56.423346 | controller | Wednesday 26 November 2025  07:36:56 +0000 (0:00:00.018)       0:02:55.665 ****
2025-11-26 07:36:56.423383 | controller | ok: [instance]
2025-11-26 07:36:56.823002 | controller |
2025-11-26 07:36:56.823032 | controller | TASK [libvirt_manager : Add user if not exists in libvirt group] ***************
2025-11-26 07:36:56.823041 | controller | Wednesday 26 November 2025  07:36:56 +0000 (0:00:00.287)       0:02:55.952 ****
2025-11-26 07:36:56.823051 | controller | changed: [instance]
2025-11-26 07:36:57.123155 | controller |
2025-11-26 07:36:57.123187 | controller | TASK [libvirt_manager : Allow QEMU on home directory for the storage access] ***
2025-11-26 07:36:57.123195 | controller | Wednesday 26 November 2025  07:36:56 +0000 (0:00:00.399)       0:02:56.352 ****
2025-11-26 07:36:57.123205 | controller | changed: [instance]
2025-11-26 07:36:57.398697 | controller |
2025-11-26 07:36:57.398727 | controller | TASK [libvirt_manager : Inject system connection parameters in bashrc] *********
2025-11-26 07:36:57.398735 | controller | Wednesday 26 November 2025  07:36:57 +0000 (0:00:00.300)       0:02:56.652 ****
2025-11-26 07:36:57.398745 | controller | [WARNING]: Reset is not implemented for this connection
2025-11-26 07:36:57.420902 | controller | changed: [instance]
2025-11-26 07:36:57.420951 | controller |
2025-11-26 07:36:57.420960 | controller | TASK [libvirt_manager : Ensure we reload user env] *****************************
2025-11-26 07:36:57.420967 | controller | Wednesday 26 November 2025  07:36:57 +0000 (0:00:00.271)       0:02:56.923 ****
2025-11-26 07:36:57.420972 | controller |
2025-11-26 07:36:57.420978 | controller | PLAY RECAP *********************************************************************
2025-11-26 07:36:57.420984 | controller | instance                   : ok=68   changed=43   unreachable=0    failed=0    skipped=34   rescued=0    ignored=0
2025-11-26 07:36:57.420989 | controller |
2025-11-26 07:36:57.420995 | controller | Wednesday 26 November 2025  07:36:57 +0000 (0:00:00.025)       0:02:56.949 ****
2025-11-26 07:36:57.421000 | controller | ===============================================================================
2025-11-26 07:36:57.421008 | controller | libvirt_manager : Install packages required for using KVM -------------- 94.10s
2025-11-26 07:36:57.421815 | controller | test_deps : Install selinux python libs -------------------------------- 47.64s
2025-11-26 07:36:57.422832 | controller | repo_setup : Initialize python venv and install requirements ------------ 7.91s
2025-11-26 07:36:57.422865 | controller | Install some debug utils ------------------------------------------------ 4.25s
2025-11-26 07:36:57.422873 | controller | test_deps : Install python yaml libs ------------------------------------ 1.23s
2025-11-26 07:36:57.422879 | controller | repo_setup : Get repo-setup repository ---------------------------------- 1.08s
2025-11-26 07:36:57.422884 | controller | libvirt_manager : Ensure firewalld service is up ------------------------ 0.82s
2025-11-26 07:36:57.422890 | controller | Gathering Facts --------------------------------------------------------- 0.82s
2025-11-26 07:36:57.422896 | controller | repo_setup : Run repo-setup --------------------------------------------- 0.81s
2025-11-26 07:36:57.422901 | controller | test_deps : Disable ubi 9 repos ----------------------------------------- 0.75s
2025-11-26 07:36:57.422911 | controller | repo_setup : Install repo-setup package --------------------------------- 0.75s
2025-11-26 07:36:57.481183 | controller | libvirt_manager : Reload systemctl and start/enable virtproxyd.service --- 0.71s
2025-11-26 07:36:57.481215 | controller | repo_setup : Make sure git-core package is installed -------------------- 0.67s
2025-11-26 07:36:57.481223 | controller | libvirt_manager : Restart service polkit service ------------------------ 0.63s
2025-11-26 07:36:57.481229 | controller | repo_setup : Ensure directories are present ----------------------------- 0.57s
2025-11-26 07:36:57.481235 | controller | repo_setup : Run repo-setup-get-hash ------------------------------------ 0.54s
2025-11-26 07:36:57.481240 | controller | repo_setup : Dump full hash in delorean.repo.md5 file ------------------- 0.43s
2025-11-26 07:36:57.481246 | controller | libvirt_manager : Add user if not exists in libvirt group --------------- 0.40s
2025-11-26 07:36:57.481251 | controller | libvirt_manager : Enable UNIX socket PolicyKit auth --------------------- 0.38s
2025-11-26 07:36:57.481257 | controller | libvirt_manager : Ensure read-only socket is enabled for proxy. --------- 0.35s
2025-11-26 07:36:57.481267 | controller | INFO     Running default > converge
2025-11-26 07:36:57.911578 | controller |
2025-11-26 07:36:57.911805 | controller | PLAY [Converge] ****************************************************************
2025-11-26 07:36:57.911960 | controller |
2025-11-26 07:36:57.912106 | controller | TASK [Gathering Facts] *********************************************************
2025-11-26 07:36:57.912248 | controller | Wednesday 26 November 2025  07:36:57 +0000 (0:00:00.013)       0:00:00.013 ****
2025-11-26 07:36:58.684720 | controller | ok: [instance]
2025-11-26 07:36:59.036342 | controller |
2025-11-26 07:36:59.036375 | controller | TASK [Crate SSH keypair] *******************************************************
2025-11-26 07:36:59.036383 | controller | Wednesday 26 November 2025  07:36:58 +0000 (0:00:00.773)       0:00:00.786 ****
2025-11-26 07:36:59.036394 | controller | changed: [instance]
2025-11-26 07:36:59.516696 | controller |
2025-11-26 07:36:59.516727 | controller | TASK [Enable forwarding in the libvirt zone] ***********************************
2025-11-26 07:36:59.516735 | controller | Wednesday 26 November 2025  07:36:59 +0000 (0:00:00.351)       0:00:01.138 ****
2025-11-26 07:36:59.516746 | controller | changed: [instance]
2025-11-26 07:37:00.473854 | controller |
2025-11-26 07:37:00.473884 | controller | TASK [Restart firewalld.service] ***********************************************
2025-11-26 07:37:00.473893 | controller | Wednesday 26 November 2025  07:36:59 +0000 (0:00:00.480)       0:00:01.618 ****
2025-11-26 07:37:00.473904 | controller | changed: [instance]
2025-11-26 07:37:00.473929 | controller |
2025-11-26 07:37:00.473935 | controller | TASK [Discover latest image] ***************************************************
2025-11-26 07:37:00.473943 | controller | Wednesday 26 November 2025  07:37:00 +0000 (0:00:00.957)       0:00:02.575 ****
2025-11-26 07:37:00.512284 | controller |
2025-11-26 07:37:02.052945 | controller | TASK [discover_latest_image : Get latest image] ********************************
2025-11-26 07:37:02.052976 | controller | Wednesday 26 November 2025  07:37:00 +0000 (0:00:00.038)       0:00:02.614 ****
2025-11-26 07:37:02.052987 | controller | changed: [instance]
2025-11-26 07:37:02.078095 | controller |
2025-11-26 07:37:02.078131 | controller | TASK [discover_latest_image : Export facts accordingly] ************************
2025-11-26 07:37:02.078146 | controller | Wednesday 26 November 2025  07:37:02 +0000 (0:00:01.540)       0:00:04.154 ****
2025-11-26 07:37:02.078158 | controller | ok: [instance]
2025-11-26 07:37:22.947059 | controller |
2025-11-26 07:37:22.947099 | controller | TASK [Download latest image] ***************************************************
2025-11-26 07:37:22.947108 | controller | Wednesday 26 November 2025  07:37:02 +0000 (0:00:00.025)       0:00:04.179 ****
2025-11-26 07:37:22.947119 | controller | changed: [instance]
2025-11-26 07:37:22.947138 | controller |
2025-11-26 07:37:22.947345 | controller | TASK [Build nat64 appliance image] *********************************************
2025-11-26 07:37:22.983913 | controller | Wednesday 26 November 2025  07:37:22 +0000 (0:00:20.869)       0:00:25.049 ****
2025-11-26 07:37:22.983955 | controller |
2025-11-26 07:37:23.474297 | controller | TASK [nat64_appliance : Ensure needed directories exist] ***********************
2025-11-26 07:37:23.474332 | controller | Wednesday 26 November 2025  07:37:22 +0000 (0:00:00.036)       0:00:25.085 ****
2025-11-26 07:37:23.474353 | controller | ok: [instance] => (item=artifacts)
2025-11-26 07:37:23.666959 | controller | ok: [instance] => (item=logs)
2025-11-26 07:37:23.666988 | controller |
2025-11-26 07:37:23.666997 | controller | TASK [nat64_appliance : Ensure working directory exists] ***********************
2025-11-26 07:37:23.667003 | controller | Wednesday 26 November 2025  07:37:23 +0000 (0:00:00.490)       0:00:25.576 ****
2025-11-26 07:37:23.667014 | controller | changed: [instance]
2025-11-26 07:37:28.086124 | controller |
2025-11-26 07:37:28.086156 | controller | TASK [nat64_appliance : Install required RPM packages] *************************
2025-11-26 07:37:28.086165 | controller | Wednesday 26 November 2025  07:37:23 +0000 (0:00:00.192)       0:00:25.768 ****
2025-11-26 07:37:28.086175 | controller | ok: [instance]
2025-11-26 07:37:36.301974 | controller |
2025-11-26 07:37:36.302020 | controller | TASK [nat64_appliance : Install diskimage-builder in virtualenv] ***************
2025-11-26 07:37:36.302029 | controller | Wednesday 26 November 2025  07:37:28 +0000 (0:00:04.419)       0:00:30.187 ****
2025-11-26 07:37:36.302040 | controller | changed: [instance]
2025-11-26 07:37:36.302396 | controller |
2025-11-26 07:37:46.244171 | controller | TASK [nat64_appliance : Copy files to cifmw_nat64_appliance_dir] ***************
2025-11-26 07:37:46.244202 | controller | Wednesday 26 November 2025  07:37:36 +0000 (0:00:08.214)       0:00:38.402 ****
2025-11-26 07:37:46.244214 | controller | changed: [instance] => (item=elements/)
2025-11-26 07:37:47.325832 | controller | changed: [instance] => (item=nat64-appliance.yaml)
2025-11-26 07:37:47.325864 | controller |
2025-11-26 07:37:47.325872 | controller | TASK [nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element)] ***
2025-11-26 07:37:47.325878 | controller | Wednesday 26 November 2025  07:37:46 +0000 (0:00:09.942)       0:00:48.345 ****
2025-11-26 07:37:47.325889 | controller | changed: [instance]
2025-11-26 07:42:16.225964 | controller |
2025-11-26 07:42:16.226192 | controller | TASK [nat64_appliance : Build the nat64-appliance image using DIB] *************
2025-11-26 07:42:16.226207 | controller | Wednesday 26 November 2025  07:37:47 +0000 (0:00:01.081)       0:00:49.427 ****
2025-11-26 07:42:16.226222 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-11-26 07:42:16.453319 | controller | changed: [instance]
2025-11-26 07:42:16.453349 | controller |
2025-11-26 07:42:16.453358 | controller | TASK [Fix permissions on logs dir - because we ran dib as root] ****************
2025-11-26 07:42:16.453365 | controller | Wednesday 26 November 2025  07:42:16 +0000 (0:04:28.900)       0:05:18.327 ****
2025-11-26 07:42:16.453375 | controller | changed: [instance]
2025-11-26 07:42:16.453401 | controller |
2025-11-26 07:42:16.453677 | controller | TASK [Fix permissions on nat64_appliance dir - because we ran dib as root] *****
2025-11-26 07:42:23.850017 | controller | Wednesday 26 November 2025  07:42:16 +0000 (0:00:00.227)       0:05:18.555 ****
2025-11-26 07:42:23.850053 | controller | changed: [instance]
2025-11-26 07:42:23.896122 | controller |
2025-11-26 07:42:23.896141 | controller | TASK [Deploy the nat64 appliance and networks] *********************************
2025-11-26 07:42:23.896149 | controller | Wednesday 26 November 2025  07:42:23 +0000 (0:00:07.396)       0:05:25.951 ****
2025-11-26 07:42:23.896158 | controller |
2025-11-26 07:42:23.953828 | controller | TASK [nat64_appliance : Set MAC address facts] *********************************
2025-11-26 07:42:23.953847 | controller | Wednesday 26 November 2025  07:42:23 +0000 (0:00:00.046)       0:05:25.998 ****
2025-11-26 07:42:23.953858 | controller | ok: [instance]
2025-11-26 07:42:23.954057 | controller |
2025-11-26 07:42:23.954080 | controller | TASK [nat64_appliance : Create the IPv4 libvirt network for nat64] *************
2025-11-26 07:42:24.743496 | controller | Wednesday 26 November 2025  07:42:23 +0000 (0:00:00.057)       0:05:26.055 ****
2025-11-26 07:42:24.743531 | controller | changed: [instance]
2025-11-26 07:42:25.067182 | controller |
2025-11-26 07:42:25.067214 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is created/started] ***
2025-11-26 07:42:25.067222 | controller | Wednesday 26 November 2025  07:42:24 +0000 (0:00:00.789)       0:05:26.845 ****
2025-11-26 07:42:25.067237 | controller | ok: [instance]
2025-11-26 07:42:25.286557 | controller |
2025-11-26 07:42:25.286586 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is active] ***
2025-11-26 07:42:25.286595 | controller | Wednesday 26 November 2025  07:42:25 +0000 (0:00:00.323)       0:05:27.168 ****
2025-11-26 07:42:25.286611 | controller | ok: [instance]
2025-11-26 07:42:25.498050 | controller |
2025-11-26 07:42:25.498079 | controller | TASK [nat64_appliance : Ensure the IPv4 libvirt network for nat64 is enabled to autostart] ***
2025-11-26 07:42:25.498088 | controller | Wednesday 26 November 2025  07:42:25 +0000 (0:00:00.219)       0:05:27.388 ****
2025-11-26 07:42:25.498098 | controller | changed: [instance]
2025-11-26 07:42:25.716369 | controller |
2025-11-26 07:42:25.716398 | controller | TASK [nat64_appliance : Create the IPv6 libvirt network for nat64] *************
2025-11-26 07:42:25.716406 | controller | Wednesday 26 November 2025  07:42:25 +0000 (0:00:00.211)       0:05:27.599 ****
2025-11-26 07:42:25.716417 | controller | changed: [instance]
2025-11-26 07:42:25.942900 | controller |
2025-11-26 07:42:25.942937 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is created/started] ***
2025-11-26 07:42:25.942946 | controller | Wednesday 26 November 2025  07:42:25 +0000 (0:00:00.218)       0:05:27.818 ****
2025-11-26 07:42:25.942957 | controller | ok: [instance]
2025-11-26 07:42:26.164861 | controller |
2025-11-26 07:42:26.164889 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 network is active] ***
2025-11-26 07:42:26.164898 | controller | Wednesday 26 November 2025  07:42:25 +0000 (0:00:00.226)       0:05:28.044 ****
2025-11-26 07:42:26.164908 | controller | ok: [instance]
2025-11-26 07:42:26.164930 | controller |
2025-11-26 07:42:26.164938 | controller | TASK [nat64_appliance : Ensure the IPv6 libvirt network for nat64 is enabled to autostart] ***
2025-11-26 07:42:26.164999 | controller | Wednesday 26 November 2025  07:42:26 +0000 (0:00:00.222)       0:05:28.266 ****
2025-11-26 07:42:26.372333 | controller | changed: [instance]
2025-11-26 07:42:27.117362 | controller |
2025-11-26 07:42:27.117391 | controller | TASK [nat64_appliance : Make sure all bridges are in the libvirt firewalld zone] ***
2025-11-26 07:42:27.117399 | controller | Wednesday 26 November 2025  07:42:26 +0000 (0:00:00.207)       0:05:28.474 ****
2025-11-26 07:42:27.117410 | controller | changed: [instance] => (item=br-64v6)
2025-11-26 07:42:27.927510 | controller | changed: [instance] => (item=br-64v4)
2025-11-26 07:42:27.927542 | controller |
2025-11-26 07:42:27.927550 | controller | TASK [nat64_appliance : Restart firewalld.service] *****************************
2025-11-26 07:42:27.927556 | controller | Wednesday 26 November 2025  07:42:27 +0000 (0:00:00.745)       0:05:29.219 ****
2025-11-26 07:42:27.927566 | controller | changed: [instance]
2025-11-26 07:42:27.956595 | controller |
2025-11-26 07:42:27.956619 | controller | TASK [nat64_appliance : Generate nat64-appliance UUID] *************************
2025-11-26 07:42:27.956627 | controller | Wednesday 26 November 2025  07:42:27 +0000 (0:00:00.810)       0:05:30.029 ****
2025-11-26 07:42:27.956636 | controller | ok: [instance]
2025-11-26 07:42:27.992211 | controller |
2025-11-26 07:42:27.992233 | controller | TASK [Create the config-drive ISO for the nat64-appliance] *********************
2025-11-26 07:42:27.992241 | controller | Wednesday 26 November 2025  07:42:27 +0000 (0:00:00.029)       0:05:30.058 ****
2025-11-26 07:42:27.992250 | controller |
2025-11-26 07:42:28.364572 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-11-26 07:42:28.364601 | controller | Wednesday 26 November 2025  07:42:27 +0000 (0:00:00.035)       0:05:30.094 ****
2025-11-26 07:42:28.364614 | controller | ok: [instance] => (item=artifacts)
2025-11-26 07:42:29.763904 | controller | ok: [instance] => (item=logs)
2025-11-26 07:42:29.763936 | controller |
2025-11-26 07:42:29.763945 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-11-26 07:42:29.763951 | controller | Wednesday 26 November 2025  07:42:28 +0000 (0:00:00.371)       0:05:30.466 ****
2025-11-26 07:42:29.763961 | controller | ok: [instance]
2025-11-26 07:42:29.763985 | controller |
2025-11-26 07:42:29.763993 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-11-26 07:42:29.764101 | controller | Wednesday 26 November 2025  07:42:29 +0000 (0:00:01.399)       0:05:31.865 ****
2025-11-26 07:42:29.968732 | controller | changed: [instance]
2025-11-26 07:42:30.314609 | controller |
2025-11-26 07:42:30.314639 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-11-26 07:42:30.314648 | controller | Wednesday 26 November 2025  07:42:29 +0000 (0:00:00.204)       0:05:32.070 ****
2025-11-26 07:42:30.314658 | controller | changed: [instance]
2025-11-26 07:42:30.690380 | controller |
2025-11-26 07:42:30.690411 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-11-26 07:42:30.690419 | controller | Wednesday 26 November 2025  07:42:30 +0000 (0:00:00.345)       0:05:32.416 ****
2025-11-26 07:42:30.690429 | controller | changed: [instance]
2025-11-26 07:42:31.058650 | controller |
2025-11-26 07:42:31.058681 | controller | TASK [config_drive : Generate network-data] ************************************
2025-11-26 07:42:31.058694 | controller | Wednesday 26 November 2025  07:42:30 +0000 (0:00:00.375)       0:05:32.792 ****
2025-11-26 07:42:31.058705 | controller | changed: [instance]
2025-11-26 07:42:31.251674 | controller |
2025-11-26 07:42:31.251704 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-11-26 07:42:31.251712 | controller | Wednesday 26 November 2025  07:42:31 +0000 (0:00:00.368)       0:05:33.160 ****
2025-11-26 07:42:31.251722 | controller | ok: [instance]
2025-11-26 07:42:31.268756 | controller |
2025-11-26 07:42:31.268773 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-11-26 07:42:31.268797 | controller | Wednesday 26 November 2025  07:42:31 +0000 (0:00:00.193)       0:05:33.353 ****
2025-11-26 07:42:31.268807 | controller | skipping: [instance]
2025-11-26 07:42:31.488878 | controller |
2025-11-26 07:42:31.488917 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-11-26 07:42:31.488926 | controller | Wednesday 26 November 2025  07:42:31 +0000 (0:00:00.017)       0:05:33.370 ****
2025-11-26 07:42:31.488938 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-11-26 07:42:32.633200 | controller | changed: [instance]
2025-11-26 07:42:32.633245 | controller |
2025-11-26 07:42:32.633254 | controller | TASK [nat64_appliance : Define nat64-appliance VM] *****************************
2025-11-26 07:42:32.633261 | controller | Wednesday 26 November 2025  07:42:31 +0000 (0:00:00.219)       0:05:33.590 ****
2025-11-26 07:42:32.633272 | controller | changed: [instance]
2025-11-26 07:42:33.199863 | controller |
2025-11-26 07:42:33.199896 | controller | TASK [nat64_appliance : Start nat64-appliance VM] ******************************
2025-11-26 07:42:33.199904 | controller | Wednesday 26 November 2025  07:42:32 +0000 (0:00:01.144)       0:05:34.735 ****
2025-11-26 07:42:33.199915 | controller | changed: [instance]
2025-11-26 07:42:33.224808 | controller |
2025-11-26 07:42:33.224840 | controller | TASK [nat64_appliance : Set nat64 facts] ***************************************
2025-11-26 07:42:33.224850 | controller | Wednesday 26 November 2025  07:42:33 +0000 (0:00:00.566)       0:05:35.301 ****
2025-11-26 07:42:33.224862 | controller | ok: [instance]
2025-11-26 07:42:33.266711 | controller |
2025-11-26 07:42:33.266741 | controller | TASK [Set MAC address facts] ***************************************************
2025-11-26 07:42:33.266749 | controller | Wednesday 26 November 2025  07:42:33 +0000 (0:00:00.025)       0:05:35.326 ****
2025-11-26 07:42:33.266759 | controller | ok: [instance]
2025-11-26 07:42:33.533114 | controller |
2025-11-26 07:42:33.533150 | controller | TASK [Define a IPv6 network for test node] *************************************
2025-11-26 07:42:33.533158 | controller | Wednesday 26 November 2025  07:42:33 +0000 (0:00:00.041)       0:05:35.368 ****
2025-11-26 07:42:33.533168 | controller | changed: [instance]
2025-11-26 07:42:33.811369 | controller |
2025-11-26 07:42:33.811399 | controller | TASK [Create a IPv6 network for test node] *************************************
2025-11-26 07:42:33.811407 | controller | Wednesday 26 November 2025  07:42:33 +0000 (0:00:00.266)       0:05:35.634 ****
2025-11-26 07:42:33.811417 | controller | ok: [instance]
2025-11-26 07:42:34.051398 | controller |
2025-11-26 07:42:34.051426 | controller | TASK [Ensure the IPv6 network for test node is active] *************************
2025-11-26 07:42:34.051435 | controller | Wednesday 26 November 2025  07:42:33 +0000 (0:00:00.275)       0:05:35.910 ****
2025-11-26 07:42:34.051445 | controller | ok: [instance]
2025-11-26 07:42:34.273803 | controller |
2025-11-26 07:42:34.273833 | controller | TASK [Ensure the IPv6 network for test node is enabled to autostart] ***********
2025-11-26 07:42:34.273841 | controller | Wednesday 26 November 2025  07:42:34 +0000 (0:00:00.240)       0:05:36.151 ****
2025-11-26 07:42:34.273852 | controller | changed: [instance]
2025-11-26 07:42:34.597842 | controller |
2025-11-26 07:42:34.597872 | controller | TASK [Make sure br-mol bridge is in the libvirt firewalld zone] ****************
2025-11-26 07:42:34.597886 | controller | Wednesday 26 November 2025  07:42:34 +0000 (0:00:00.224)       0:05:36.375 ****
2025-11-26 07:42:34.597897 | controller | changed: [instance]
2025-11-26 07:42:35.370319 | controller |
2025-11-26 07:42:35.370349 | controller | TASK [Restart firewalld.service] ***********************************************
2025-11-26 07:42:35.370358 | controller | Wednesday 26 November 2025  07:42:34 +0000 (0:00:00.323)       0:05:36.699 ****
2025-11-26 07:42:35.370368 | controller | changed: [instance]
2025-11-26 07:42:35.404895 | controller |
2025-11-26 07:42:35.404918 | controller | TASK [Generate test node UUID] *************************************************
2025-11-26 07:42:35.404925 | controller | Wednesday 26 November 2025  07:42:35 +0000 (0:00:00.772)       0:05:37.472 ****
2025-11-26 07:42:35.404935 | controller | ok: [instance]
2025-11-26 07:42:35.405049 | controller |
2025-11-26 07:42:35.405059 | controller | TASK [Make an a copy of the discovered/downloaded image] ***********************
2025-11-26 07:42:35.405067 | controller | Wednesday 26 November 2025  07:42:35 +0000 (0:00:00.032)       0:05:37.504 ****
2025-11-26 07:42:44.372726 | controller | changed: [instance]
2025-11-26 07:42:44.417709 | controller |
2025-11-26 07:42:44.417731 | controller | TASK [Create the config-drive ISO for the test node] ***************************
2025-11-26 07:42:44.417739 | controller | Wednesday 26 November 2025  07:42:44 +0000 (0:00:08.970)       0:05:46.474 ****
2025-11-26 07:42:44.417748 | controller |
2025-11-26 07:42:44.868358 | controller | TASK [config_drive : Ensure needed directories exist] **************************
2025-11-26 07:42:44.868388 | controller | Wednesday 26 November 2025  07:42:44 +0000 (0:00:00.045)       0:05:46.519 ****
2025-11-26 07:42:44.868400 | controller | ok: [instance] => (item=artifacts)
2025-11-26 07:42:46.166201 | controller | ok: [instance] => (item=logs)
2025-11-26 07:42:46.166234 | controller |
2025-11-26 07:42:46.166243 | controller | TASK [config_drive : Install required RPM packages] ****************************
2025-11-26 07:42:46.166250 | controller | Wednesday 26 November 2025  07:42:44 +0000 (0:00:00.450)       0:05:46.970 ****
2025-11-26 07:42:46.166260 | controller | ok: [instance]
2025-11-26 07:42:46.382881 | controller |
2025-11-26 07:42:46.382909 | controller | TASK [config_drive : Crate config drive instance directory] ********************
2025-11-26 07:42:46.382917 | controller | Wednesday 26 November 2025  07:42:46 +0000 (0:00:01.297)       0:05:48.267 ****
2025-11-26 07:42:46.382927 | controller | changed: [instance]
2025-11-26 07:42:46.383125 | controller |
2025-11-26 07:42:46.736977 | controller | TASK [config_drive : Generate meta-data] ***************************************
2025-11-26 07:42:46.737008 | controller | Wednesday 26 November 2025  07:42:46 +0000 (0:00:00.217)       0:05:48.484 ****
2025-11-26 07:42:46.737020 | controller | changed: [instance]
2025-11-26 07:42:47.135223 | controller |
2025-11-26 07:42:47.135255 | controller | TASK [config_drive : Generate user-data] ***************************************
2025-11-26 07:42:47.135263 | controller | Wednesday 26 November 2025  07:42:46 +0000 (0:00:00.353)       0:05:48.838 ****
2025-11-26 07:42:47.135273 | controller | changed: [instance]
2025-11-26 07:42:47.497325 | controller |
2025-11-26 07:42:47.497357 | controller | TASK [config_drive : Generate network-data] ************************************
2025-11-26 07:42:47.497366 | controller | Wednesday 26 November 2025  07:42:47 +0000 (0:00:00.394)       0:05:49.233 ****
2025-11-26 07:42:47.497376 | controller | changed: [instance]
2025-11-26 07:42:47.676873 | controller |
2025-11-26 07:42:47.676902 | controller | TASK [config_drive : Check ISO availability] ***********************************
2025-11-26 07:42:47.676910 | controller | Wednesday 26 November 2025  07:42:47 +0000 (0:00:00.365)       0:05:49.599 ****
2025-11-26 07:42:47.676921 | controller | ok: [instance]
2025-11-26 07:42:47.695379 | controller |
2025-11-26 07:42:47.695401 | controller | TASK [config_drive : Assert we don't try to change an existing ISO] ************
2025-11-26 07:42:47.695409 | controller | Wednesday 26 November 2025  07:42:47 +0000 (0:00:00.177)       0:05:49.776 ****
2025-11-26 07:42:47.695418 | controller | skipping: [instance]
2025-11-26 07:42:47.932865 | controller |
2025-11-26 07:42:47.932898 | controller | TASK [config_drive : Generate nocloud iso image] *******************************
2025-11-26 07:42:47.932906 | controller | Wednesday 26 November 2025  07:42:47 +0000 (0:00:00.021)       0:05:49.797 ****
2025-11-26 07:42:47.932916 | controller | Follow script's output here: /home/zuul/ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-11-26 07:42:47.932949 | controller | changed: [instance]
2025-11-26 07:42:47.932958 | controller |
2025-11-26 07:42:47.933010 | controller | TASK [Define test-node VM] *****************************************************
2025-11-26 07:42:47.933133 | controller | Wednesday 26 November 2025  07:42:47 +0000 (0:00:00.211)       0:05:50.009 ****
2025-11-26 07:42:48.171242 | controller | changed: [instance]
2025-11-26 07:42:48.662127 | controller |
2025-11-26 07:42:48.662164 | controller | TASK [Start test-node VM] ******************************************************
2025-11-26 07:42:48.662173 | controller | Wednesday 26 November 2025  07:42:48 +0000 (0:00:00.263)       0:05:50.273 ****
2025-11-26 07:42:48.662183 | controller | changed: [instance]
2025-11-26 07:43:17.442009 | controller |
2025-11-26 07:43:17.442050 | controller | TASK [Wait for test node to be reachable via ssh] ******************************
2025-11-26 07:43:17.442058 | controller | Wednesday 26 November 2025  07:42:48 +0000 (0:00:00.490)       0:05:50.763 ****
2025-11-26 07:43:17.442069 | controller | ok: [instance]
2025-11-26 07:43:17.466994 | controller |
2025-11-26 07:43:17.467013 | controller | TASK [Add test node to inventory] **********************************************
2025-11-26 07:43:17.467021 | controller | Wednesday 26 November 2025  07:43:17 +0000 (0:00:28.779)       0:06:19.543 ****
2025-11-26 07:43:17.467030 | controller | changed: [instance]
2025-11-26 07:43:17.489614 | controller |
2025-11-26 07:43:17.489633 | controller | TASK [Add nat64 appliance to the invetory] *************************************
2025-11-26 07:43:17.489640 | controller | Wednesday 26 November 2025  07:43:17 +0000 (0:00:00.022)       0:06:19.566 ****
2025-11-26 07:43:17.489649 | controller | changed: [instance]
2025-11-26 07:43:37.525816 | controller |
2025-11-26 07:43:37.526009 | controller | TASK [Wait a little to let the test instance boot.] ****************************
2025-11-26 07:43:37.526054 | controller | Wednesday 26 November 2025  07:43:17 +0000 (0:00:00.023)       0:06:19.590 ****
2025-11-26 07:43:37.526066 | controller | Pausing for 20 seconds
2025-11-26 07:43:44.003597 | controller | ok: [instance]
2025-11-26 07:43:44.003636 | controller |
2025-11-26 07:43:44.003645 | controller | TASK [Run some commands to test the nat64-appliance DNS64 functions] ***********
2025-11-26 07:43:44.003651 | controller | Wednesday 26 November 2025  07:43:37 +0000 (0:00:20.036)       0:06:39.626 ****
2025-11-26 07:43:44.003661 | controller | changed: [instance]
2025-11-26 07:43:45.113652 | controller |
2025-11-26 07:43:45.113683 | controller | TASK [Grab some info from the test node] ***************************************
2025-11-26 07:43:45.113691 | controller | Wednesday 26 November 2025  07:43:44 +0000 (0:00:06.478)       0:06:46.105 ****
2025-11-26 07:43:45.113702 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-11-26 07:43:46.137882 | controller |
2025-11-26 07:43:46.137913 | controller | TASK [Grab some info from the nat64 appliance] *********************************
2025-11-26 07:43:46.137922 | controller | Wednesday 26 November 2025  07:43:45 +0000 (0:00:01.110)       0:06:47.215 ****
2025-11-26 07:43:46.137932 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-11-26 07:43:46.725639 | controller |
2025-11-26 07:43:46.725670 | controller | TASK [Grab the journal from the nat64 appliance] *******************************
2025-11-26 07:43:46.725678 | controller | Wednesday 26 November 2025  07:43:46 +0000 (0:00:01.024)       0:06:48.239 ****
2025-11-26 07:43:46.725688 | controller | changed: [instance -> nat64-appliance(172.31.255.2)]
2025-11-26 07:43:47.258874 | controller |
2025-11-26 07:43:47.258905 | controller | TASK [Grab some info from hypervisor] ******************************************
2025-11-26 07:43:47.258914 | controller | Wednesday 26 November 2025  07:43:46 +0000 (0:00:00.587)       0:06:48.827 ****
2025-11-26 07:43:47.258924 | controller | changed: [instance]
2025-11-26 07:43:47.258949 | controller |
2025-11-26 07:43:47.258957 | controller | TASK [Write test-node info to file] ********************************************
2025-11-26 07:43:47.259084 | controller | Wednesday 26 November 2025  07:43:47 +0000 (0:00:00.533)       0:06:49.360 ****
2025-11-26 07:43:47.596820 | controller | changed: [instance]
2025-11-26 07:43:47.931290 | controller |
2025-11-26 07:43:47.931334 | controller | TASK [Write nat64-appliance info to file] **************************************
2025-11-26 07:43:47.931343 | controller | Wednesday 26 November 2025  07:43:47 +0000 (0:00:00.337)       0:06:49.698 ****
2025-11-26 07:43:47.931353 | controller | changed: [instance]
2025-11-26 07:43:48.269522 | controller |
2025-11-26 07:43:48.269552 | controller | TASK [Write nat64-appliance journal to file] ***********************************
2025-11-26 07:43:48.269561 | controller | Wednesday 26 November 2025  07:43:47 +0000 (0:00:00.334)       0:06:50.033 ****
2025-11-26 07:43:48.269571 | controller | changed: [instance]
2025-11-26 07:43:48.597431 | controller |
2025-11-26 07:43:48.597472 | controller | TASK [Write nat64-appliance DNS64 debug to file] *******************************
2025-11-26 07:43:48.597481 | controller | Wednesday 26 November 2025  07:43:48 +0000 (0:00:00.338)       0:06:50.371 ****
2025-11-26 07:43:48.597492 | controller | changed: [instance]
2025-11-26 07:43:48.929918 | controller |
2025-11-26 07:43:48.929947 | controller | TASK [Write hypervisor info to file] *******************************************
2025-11-26 07:43:48.929955 | controller | Wednesday 26 November 2025  07:43:48 +0000 (0:00:00.327)       0:06:50.699 ****
2025-11-26 07:43:48.929966 | controller | changed: [instance]
2025-11-26 07:43:50.586494 | controller |
2025-11-26 07:43:50.586526 | controller | TASK [Ping example.com (delegate to test-node)] ********************************
2025-11-26 07:43:50.586540 | controller | Wednesday 26 November 2025  07:43:48 +0000 (0:00:00.332)       0:06:51.031 ****
2025-11-26 07:43:50.586551 | controller | changed: [instance -> test-node(2620:cf:cf:aaaa::101)]
2025-11-26 07:43:50.626682 | controller |
2025-11-26 07:43:50.626720 | controller | TASK [Debug the ping example.com result] ***************************************
2025-11-26 07:43:50.626740 | controller | Wednesday 26 November 2025  07:43:50 +0000 (0:00:01.656)       0:06:52.688 ****
2025-11-26 07:43:50.626755 | controller | ok: [instance] => (item=0) =>
2025-11-26 07:43:50.626814 | controller |   msg: '0'
2025-11-26 07:43:50.626828 | controller | ok: [instance] => (item=['PING example.com(a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5)) 56 data bytes', '64 bytes from a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5): icmp_seq=1 ttl=44 time=39.3 ms', '64 bytes from a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5): icmp_seq=2 ttl=44 time=38.8 ms', '', '--- example.com ping statistics ---', '2 packets transmitted, 2 received, 0% packet loss, time 1001ms', 'rtt min/avg/max/mdev = 38.788/39.063/39.338/0.275 ms']) =>
2025-11-26 07:43:50.626841 | controller |   msg:
2025-11-26 07:43:50.627092 | controller |   - PING example.com(a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5)) 56 data bytes
2025-11-26 07:43:50.627115 | controller |   - '64 bytes from a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5): icmp_seq=1 ttl=44 time=39.3 ms'
2025-11-26 07:43:50.627124 | controller |   - '64 bytes from a23-220-75-245.deploy.static.akamaitechnologies.com (2620:cf:cf:fcff::17dc:4bf5): icmp_seq=2 ttl=44 time=38.8 ms'
2025-11-26 07:43:50.627404 | controller |   - ''
2025-11-26 07:43:50.627725 | controller |   - '--- example.com ping statistics ---'
2025-11-26 07:43:50.627946 | controller |   - 2 packets transmitted, 2 received, 0% packet loss, time 1001ms
2025-11-26 07:43:50.627967 | controller |   - rtt min/avg/max/mdev = 38.788/39.063/39.338/0.275 ms
2025-11-26 07:43:50.628362 | controller | ok: [instance] => (item=[]) =>
2025-11-26 07:43:50.628376 | controller |   msg: []
2025-11-26 07:43:50.629203 | controller |
2025-11-26 07:43:50.629231 | controller | PLAY RECAP *********************************************************************
2025-11-26 07:43:50.629239 | controller | instance                   : ok=74   changed=50   unreachable=0    failed=0    skipped=2    rescued=0    ignored=0
2025-11-26 07:43:50.629245 | controller |
2025-11-26 07:43:50.629251 | controller | Wednesday 26 November 2025  07:43:50 +0000 (0:00:00.040)       0:06:52.728 ****
2025-11-26 07:43:50.629256 | controller | ===============================================================================
2025-11-26 07:43:50.629262 | controller | nat64_appliance : Build the nat64-appliance image using DIB ----------- 268.90s
2025-11-26 07:43:50.629272 | controller | Wait for test node to be reachable via ssh ----------------------------- 28.78s
2025-11-26 07:43:50.629389 | controller | Download latest image -------------------------------------------------- 20.87s
2025-11-26 07:43:50.629404 | controller | Wait a little to let the test instance boot. --------------------------- 20.04s
2025-11-26 07:43:50.629410 | controller | nat64_appliance : Copy files to cifmw_nat64_appliance_dir --------------- 9.94s
2025-11-26 07:43:50.629431 | controller | Make an a copy of the discovered/downloaded image ----------------------- 8.97s
2025-11-26 07:43:50.629437 | controller | nat64_appliance : Install diskimage-builder in virtualenv --------------- 8.22s
2025-11-26 07:43:50.629443 | controller | Fix permissions on nat64_appliance dir - because we ran dib as root ----- 7.40s
2025-11-26 07:43:50.629448 | controller | Run some commands to test the nat64-appliance DNS64 functions ----------- 6.48s
2025-11-26 07:43:50.629453 | controller | nat64_appliance : Install required RPM packages ------------------------- 4.42s
2025-11-26 07:43:50.629470 | controller | Ping example.com (delegate to test-node) -------------------------------- 1.66s
2025-11-26 07:43:50.629506 | controller | discover_latest_image : Get latest image -------------------------------- 1.54s
2025-11-26 07:43:50.629625 | controller | config_drive : Install required RPM packages ---------------------------- 1.40s
2025-11-26 07:43:50.629735 | controller | config_drive : Install required RPM packages ---------------------------- 1.30s
2025-11-26 07:43:50.629892 | controller | nat64_appliance : Define nat64-appliance VM ----------------------------- 1.14s
2025-11-26 07:43:50.630001 | controller | Grab some info from the test node --------------------------------------- 1.11s
2025-11-26 07:43:50.630122 | controller | nat64_appliance : Clone edpm-image-builder (reset-bls-entries dib element) --- 1.08s
2025-11-26 07:43:50.630225 | controller | Grab some info from the nat64 appliance --------------------------------- 1.02s
2025-11-26 07:43:50.630332 | controller | Restart firewalld.service ----------------------------------------------- 0.96s
2025-11-26 07:43:50.630567 | controller | nat64_appliance : Restart firewalld.service ----------------------------- 0.81s
2025-11-26 07:43:50.689976 | controller | INFO     Running default > cleanup
2025-11-26 07:43:51.146256 | controller |
2025-11-26 07:43:51.146386 | controller | PLAY [Cleanup] *****************************************************************
2025-11-26 07:43:51.146561 | controller |
2025-11-26 07:43:51.146665 | controller | TASK [Gathering Facts] *********************************************************
2025-11-26 07:43:51.146807 | controller | Wednesday 26 November 2025  07:43:51 +0000 (0:00:00.052)       0:00:00.052 ****
2025-11-26 07:43:52.098401 | controller | ok: [instance]
2025-11-26 07:43:52.669834 | controller |
2025-11-26 07:43:52.669866 | controller | TASK [Destroy the test-node] ***************************************************
2025-11-26 07:43:52.669874 | controller | Wednesday 26 November 2025  07:43:52 +0000 (0:00:00.952)       0:00:01.005 ****
2025-11-26 07:43:52.669885 | controller | ok: [instance]
2025-11-26 07:43:52.897927 | controller |
2025-11-26 07:43:52.897961 | controller | TASK [Undefine the test-node] **************************************************
2025-11-26 07:43:52.897969 | controller | Wednesday 26 November 2025  07:43:52 +0000 (0:00:00.571)       0:00:01.576 ****
2025-11-26 07:43:52.897980 | controller | ok: [instance]
2025-11-26 07:43:52.898006 | controller |
2025-11-26 07:43:52.898012 | controller | TASK [Destroy the test network] ************************************************
2025-11-26 07:43:52.898019 | controller | Wednesday 26 November 2025  07:43:52 +0000 (0:00:00.228)       0:00:01.805 ****
2025-11-26 07:43:53.273287 | controller | ok: [instance]
2025-11-26 07:43:53.492845 | controller |
2025-11-26 07:43:53.492877 | controller | TASK [Undefine the test network] ***********************************************
2025-11-26 07:43:53.492885 | controller | Wednesday 26 November 2025  07:43:53 +0000 (0:00:00.375)       0:00:02.180 ****
2025-11-26 07:43:53.492895 | controller | ok: [instance]
2025-11-26 07:43:53.526747 | controller |
2025-11-26 07:43:53.526798 | controller | TASK [Cleanup the nat64 appliance and networks] ********************************
2025-11-26 07:43:53.526809 | controller | Wednesday 26 November 2025  07:43:53 +0000 (0:00:00.219)       0:00:02.399 ****
2025-11-26 07:43:53.526820 | controller |
2025-11-26 07:43:53.829692 | controller | TASK [nat64_appliance : Cleaning up nat64_appliance image] *********************
2025-11-26 07:43:53.829727 | controller | Wednesday 26 November 2025  07:43:53 +0000 (0:00:00.034)       0:00:02.434 ****
2025-11-26 07:43:53.829739 | controller | changed: [instance]
2025-11-26 07:43:54.106709 | controller |
2025-11-26 07:43:54.106740 | controller | TASK [nat64_appliance : Get virtqemud socket] **********************************
2025-11-26 07:43:54.106749 | controller | Wednesday 26 November 2025  07:43:53 +0000 (0:00:00.302)       0:00:02.736 ****
2025-11-26 07:43:54.106764 | controller | ok: [instance]
2025-11-26 07:43:54.336273 | controller |
2025-11-26 07:43:54.336305 | controller | TASK [nat64_appliance : List VMs] **********************************************
2025-11-26 07:43:54.336313 | controller | Wednesday 26 November 2025  07:43:54 +0000 (0:00:00.277)       0:00:03.013 ****
2025-11-26 07:43:54.336323 | controller | ok: [instance]
2025-11-26 07:43:54.800952 | controller |
2025-11-26 07:43:54.800983 | controller | TASK [nat64_appliance : Stop the nat64_appliance VM] ***************************
2025-11-26 07:43:54.800991 | controller | Wednesday 26 November 2025  07:43:54 +0000 (0:00:00.229)       0:00:03.243 ****
2025-11-26 07:43:54.801001 | controller | ok: [instance]
2025-11-26 07:43:55.032346 | controller |
2025-11-26 07:43:55.032379 | controller | TASK [nat64_appliance : Undefine the nat64_appliance VM] ***********************
2025-11-26 07:43:55.032387 | controller | Wednesday 26 November 2025  07:43:54 +0000 (0:00:00.464)       0:00:03.708 ****
2025-11-26 07:43:55.032397 | controller | ok: [instance]
2025-11-26 07:43:55.812903 | controller |
2025-11-26 07:43:55.812950 | controller | TASK [nat64_appliance : Destroy the nat64 networks] ****************************
2025-11-26 07:43:55.812962 | controller | Wednesday 26 November 2025  07:43:55 +0000 (0:00:00.231)       0:00:03.939 ****
2025-11-26 07:43:55.812975 | controller | ok: [instance] => (item=nat64-net-v4)
2025-11-26 07:43:55.813006 | controller | ok: [instance] => (item=nat64-net-v6)
2025-11-26 07:43:55.813016 | controller |
2025-11-26 07:43:55.813207 | controller | TASK [nat64_appliance : Undefine the nat64 networks] ***************************
2025-11-26 07:43:56.293152 | controller | Wednesday 26 November 2025  07:43:55 +0000 (0:00:00.780)       0:00:04.720 ****
2025-11-26 07:43:56.293187 | controller | ok: [instance] => (item=nat64-net-v4)
2025-11-26 07:43:56.341354 | controller | ok: [instance] => (item=nat64-net-v6)
2025-11-26 07:43:56.341388 | controller |
2025-11-26 07:43:56.341397 | controller | PLAY RECAP *********************************************************************
2025-11-26 07:43:56.341403 | controller | instance                   : ok=12   changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0
2025-11-26 07:43:56.341409 | controller |
2025-11-26 07:43:56.341414 | controller | Wednesday 26 November 2025  07:43:56 +0000 (0:00:00.478)       0:00:05.198 ****
2025-11-26 07:43:56.341420 | controller | ===============================================================================
2025-11-26 07:43:56.341425 | controller | Gathering Facts --------------------------------------------------------- 0.95s
2025-11-26 07:43:56.341431 | controller | nat64_appliance : Destroy the nat64 networks ---------------------------- 0.78s
2025-11-26 07:43:56.341436 | controller | Destroy the test-node --------------------------------------------------- 0.57s
2025-11-26 07:43:56.341441 | controller | nat64_appliance : Undefine the nat64 networks --------------------------- 0.48s
2025-11-26 07:43:56.341446 | controller | nat64_appliance : Stop the nat64_appliance VM --------------------------- 0.46s
2025-11-26 07:43:56.341452 | controller | Destroy the test network ------------------------------------------------ 0.38s
2025-11-26 07:43:56.341457 | controller | nat64_appliance : Cleaning up nat64_appliance image --------------------- 0.30s
2025-11-26 07:43:56.341462 | controller | nat64_appliance : Get virtqemud socket ---------------------------------- 0.28s
2025-11-26 07:43:56.341468 | controller | nat64_appliance : Undefine the nat64_appliance VM ----------------------- 0.23s
2025-11-26 07:43:56.341485 | controller | nat64_appliance : List VMs ---------------------------------------------- 0.23s
2025-11-26 07:43:56.341491 | controller | Undefine the test-node -------------------------------------------------- 0.23s
2025-11-26 07:43:56.341497 | controller | Undefine the test network ----------------------------------------------- 0.22s
2025-11-26 07:43:56.341502 | controller | Cleanup the nat64 appliance and networks -------------------------------- 0.03s
2025-11-26 07:43:56.341512 | controller | INFO     Writing /tmp/report.html report.
2025-11-26 07:43:56.564348 | [controller] Waiting on logger
2025-11-26 07:44:01.696954 | [controller] Waiting on logger
2025-11-26 07:44:12.128951 | [controller] Waiting on logger
2025-11-26 07:44:22.560735 | [controller] Waiting on logger
2025-11-26 07:44:26.422161 | [Zuul] Log Stream did not terminate
2025-11-26 07:44:26.422420 | controller | changed
2025-11-26 07:44:26.446740 | 
2025-11-26 07:44:26.446812 | PLAY RECAP
2025-11-26 07:44:26.446855 | controller | ok: 4 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-11-26 07:44:26.446878 | 
2025-11-26 07:44:26.527319 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main]
2025-11-26 07:44:26.528260 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-11-26 07:44:27.051330 | 
2025-11-26 07:44:27.051465 | PLAY [Run ci/playbooks/collect-logs.yml]
2025-11-26 07:44:27.071635 | 
2025-11-26 07:44:27.071711 | TASK [Filter out host if needed]
2025-11-26 07:44:27.080095 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller
2025-11-26 07:44:27.084572 | 
2025-11-26 07:44:27.084639 | TASK [Ensure file is present]
2025-11-26 07:44:27.396476 | controller | ok
2025-11-26 07:44:27.403095 | 
2025-11-26 07:44:27.403167 | TASK [Manage molecule report file]
2025-11-26 07:44:27.423655 | [controller] Waiting on logger
2025-11-26 07:44:36.768976 | [controller] Waiting on logger
2025-11-26 07:44:47.201114 | [controller] Waiting on logger
2025-11-26 07:44:56.581585 | [controller] Waiting on logger
2025-11-26 07:44:57.725563 | [Zuul] Log Stream did not terminate
2025-11-26 07:44:57.725767 | controller | changed
2025-11-26 07:44:57.730968 | 
2025-11-26 07:44:57.731062 | TASK [Check if we get ci-framework-data basedir]
2025-11-26 07:44:57.921626 | controller | ok
2025-11-26 07:44:57.926645 | 
2025-11-26 07:44:57.926710 | TASK [Create ci-framework-data log directory for zuul]
2025-11-26 07:44:58.228759 | controller | changed
2025-11-26 07:44:58.233745 | 
2025-11-26 07:44:58.233814 | TASK [Copy ci-framework interesting files]
2025-11-26 07:45:03.260041 | controller | changed
2025-11-26 07:45:03.265455 | 
2025-11-26 07:45:03.265542 | TASK [Get SELinux listing]
2025-11-26 07:45:03.285541 | [controller] Waiting on logger
2025-11-26 07:45:12.161106 | [controller] Waiting on logger
2025-11-26 07:45:19.379601 | controller | changed
2025-11-26 07:45:19.386521 | 
2025-11-26 07:45:19.386627 | TASK [Generate log index]
2025-11-26 07:45:20.054501 | controller | changed
2025-11-26 07:45:20.059209 | 
2025-11-26 07:45:20.059278 | TASK [Get some env related data]
2025-11-26 07:45:21.121242 | [controller] Waiting on logger
2025-11-26 07:45:28.736934 | [controller] Waiting on logger
2025-11-26 07:45:31.794555 | controller | changed
2025-11-26 07:45:31.799691 | 
2025-11-26 07:45:31.799761 | TASK [Generate list of logs to collect in home directory]
2025-11-26 07:45:32.092513 | controller | ok: All paths examined
2025-11-26 07:45:32.097570 | 
2025-11-26 07:45:32.097634 | LOOP [Copy logs from home directory]
2025-11-26 07:45:32.420421 | controller | changed:
2025-11-26 07:45:32.420530 | controller | {
2025-11-26 07:45:32.420558 | controller |   "atime": 1764142399.321826,
2025-11-26 07:45:32.420578 | controller |   "ctime": 1764142417.2580376,
2025-11-26 07:45:32.420596 | controller |   "dev": 64513,
2025-11-26 07:45:32.420618 | controller |   "gid": 1000,
2025-11-26 07:45:32.420636 | controller |   "gr_name": "zuul",
2025-11-26 07:45:32.420652 | controller |   "inode": 4331927,
2025-11-26 07:45:32.420669 | controller |   "isblk": false,
2025-11-26 07:45:32.420685 | controller |   "ischr": false,
2025-11-26 07:45:32.420700 | controller |   "isdir": false,
2025-11-26 07:45:32.420716 | controller |   "isfifo": false,
2025-11-26 07:45:32.420732 | controller |   "isgid": false,
2025-11-26 07:45:32.420749 | controller |   "islnk": false,
2025-11-26 07:45:32.420766 | controller |   "isreg": true,
2025-11-26 07:45:32.420783 | controller |   "issock": false,
2025-11-26 07:45:32.420800 | controller |   "isuid": false,
2025-11-26 07:45:32.420817 | controller |   "mode": "0644",
2025-11-26 07:45:32.420833 | controller |   "mtime": 1764142417.2580376,
2025-11-26 07:45:32.420849 | controller |   "nlink": 1,
2025-11-26 07:45:32.420865 | controller |   "path": "/home/zuul/ansible.log",
2025-11-26 07:45:32.420881 | controller |   "pw_name": "zuul",
2025-11-26 07:45:32.420898 | controller |   "rgrp": true,
2025-11-26 07:45:32.420915 | controller |   "roth": true,
2025-11-26 07:45:32.420930 | controller |   "rusr": true,
2025-11-26 07:45:32.420945 | controller |   "size": 6749,
2025-11-26 07:45:32.420960 | controller |   "uid": 1000,
2025-11-26 07:45:32.420975 | controller |   "wgrp": false,
2025-11-26 07:45:32.420989 | controller |   "woth": false,
2025-11-26 07:45:32.421013 | controller |   "wusr": true,
2025-11-26 07:45:32.421031 | controller |   "xgrp": false,
2025-11-26 07:45:32.421046 | controller |   "xoth": false,
2025-11-26 07:45:32.421062 | controller |   "xusr": false
2025-11-26 07:45:32.421077 | controller | }
2025-11-26 07:45:32.432549 | 
2025-11-26 07:45:32.432674 | TASK [Copy crio stats log file]
2025-11-26 07:45:32.446277 | controller | skipping: Conditional result was False
2025-11-26 07:45:32.452319 | 
2025-11-26 07:45:32.452420 | TASK [Get SELinux related data]
2025-11-26 07:45:35.584826 | [controller] Waiting on logger
2025-11-26 07:45:43.264848 | [controller] Waiting on logger
2025-11-26 07:45:57.344882 | [controller] Waiting on logger
2025-11-26 07:46:02.685749 | [Zuul] Log Stream did not terminate
2025-11-26 07:46:02.685981 | controller | ERROR
2025-11-26 07:46:02.686106 | controller | {
2025-11-26 07:46:02.686140 | controller |   "delta": "0:00:00.010078",
2025-11-26 07:46:02.686163 | controller |   "end": "2025-11-26 07:45:32.659102",
2025-11-26 07:46:02.686185 | controller |   "msg": "non-zero return code",
2025-11-26 07:46:02.686206 | controller |   "rc": 1,
2025-11-26 07:46:02.686226 | controller |   "start": "2025-11-26 07:45:32.649024"
2025-11-26 07:46:02.686243 | controller | }
2025-11-26 07:46:02.686269 | controller | ERROR: Ignoring Errors
2025-11-26 07:46:02.691323 | 
2025-11-26 07:46:02.691401 | TASK [Create system configuration directory]
2025-11-26 07:46:02.881955 | controller | changed
2025-11-26 07:46:02.886662 | 
2025-11-26 07:46:02.886730 | TASK [Get some of the system configurations]
2025-11-26 07:46:02.909766 | [controller] Waiting on logger
2025-11-26 07:46:03.937995 | [controller] Waiting on logger
2025-11-26 07:46:08.016784 | controller | changed
2025-11-26 07:46:08.021982 | 
2025-11-26 07:46:08.022074 | TASK [Copy generated documentation if available]
2025-11-26 07:46:08.035294 | controller | skipping: Conditional result was False
2025-11-26 07:46:08.040906 | 
2025-11-26 07:46:08.040977 | TASK [Copy generated AsciiDoc documentation if available]
2025-11-26 07:46:08.054174 | controller | skipping: Conditional result was False
2025-11-26 07:46:08.060205 | 
2025-11-26 07:46:08.060269 | TASK [Compress logs bigger than 2MB]
2025-11-26 07:46:08.079986 | [controller] Waiting on logger
2025-11-26 07:46:14.291494 | controller | changed
2025-11-26 07:46:14.296796 | 
2025-11-26 07:46:14.296865 | TASK [Copy files from workspace on node]
2025-11-26 07:46:14.314777 | controller | ok
2025-11-26 07:46:14.336117 | 
2025-11-26 07:46:14.336208 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-26 07:46:14.349703 | controller | skipping: Conditional result was False
2025-11-26 07:46:14.355058 | 
2025-11-26 07:46:14.355138 | TASK [fetch-output : Set log path for single node]
2025-11-26 07:46:14.384219 | controller | ok
2025-11-26 07:46:14.389070 | 
2025-11-26 07:46:14.389154 | LOOP [fetch-output : Ensure local output dirs]
2025-11-26 07:46:14.584587 | controller -> localhost | ok: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/logs"
2025-11-26 07:46:14.584821 | controller -> localhost | changed: All items complete
2025-11-26 07:46:14.584861 | 
2025-11-26 07:46:14.760558 | controller -> localhost | changed: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/artifacts"
2025-11-26 07:46:14.934269 | controller -> localhost | changed: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/docs"
2025-11-26 07:46:14.946464 | 
2025-11-26 07:46:14.946550 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-26 07:46:15.504681 | controller | changed:
2025-11-26 07:46:15.504870 | controller | .d..t...... ./
2025-11-26 07:46:15.504901 | controller | >f+++++++++ README.html
2025-11-26 07:46:15.504923 | controller | >f+++++++++ ansible-execution.log
2025-11-26 07:46:15.504943 | controller | >f+++++++++ ansible.log
2025-11-26 07:46:15.504960 | controller | >f+++++++++ dmesg.log
2025-11-26 07:46:15.504977 | controller | >f+++++++++ installed-pkgs.log
2025-11-26 07:46:15.504994 | controller | >f+++++++++ python.log
2025-11-26 07:46:15.505031 | controller | >f+++++++++ registries.conf
2025-11-26 07:46:15.505051 | controller | >f+++++++++ report.html
2025-11-26 07:46:15.505068 | controller | >f+++++++++ selinux-denials.log
2025-11-26 07:46:15.505085 | controller | >f+++++++++ selinux-listing.log
2025-11-26 07:46:15.505100 | controller | cd+++++++++ ci-framework-data/
2025-11-26 07:46:15.505116 | controller | cd+++++++++ ci-framework-data/artifacts/
2025-11-26 07:46:15.505132 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_000_build_the_nat64_appliance.sh
2025-11-26 07:46:15.505149 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_001_generate_nocloud_iso.sh
2025-11-26 07:46:15.505165 | controller | >f+++++++++ ci-framework-data/artifacts/ci_script_002_generate_nocloud_iso.sh
2025-11-26 07:46:15.505181 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml
2025-11-26 07:46:15.505196 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/
2025-11-26 07:46:15.505210 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/0e309e38-cb06-569e-a908-cea4de886ebe/
2025-11-26 07:46:15.505225 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/0e309e38-cb06-569e-a908-cea4de886ebe/meta-data
2025-11-26 07:46:15.505241 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/0e309e38-cb06-569e-a908-cea4de886ebe/network-config
2025-11-26 07:46:15.505256 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/0e309e38-cb06-569e-a908-cea4de886ebe/user-data
2025-11-26 07:46:15.505270 | controller | cd+++++++++ ci-framework-data/artifacts/cifmw_config_drive/bb27609d-9aca-51dd-8b4f-bc5ea81aebdb/
2025-11-26 07:46:15.505285 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/bb27609d-9aca-51dd-8b4f-bc5ea81aebdb/meta-data
2025-11-26 07:46:15.505300 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/bb27609d-9aca-51dd-8b4f-bc5ea81aebdb/network-config
2025-11-26 07:46:15.505315 | controller | >f+++++++++ ci-framework-data/artifacts/cifmw_config_drive/bb27609d-9aca-51dd-8b4f-bc5ea81aebdb/user-data
2025-11-26 07:46:15.505330 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/
2025-11-26 07:46:15.505344 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml
2025-11-26 07:46:15.505358 | controller | cd+++++++++ ci-framework-data/artifacts/repositories/
2025-11-26 07:46:15.505373 | controller | >f+++++++++ ci-framework-data/artifacts/repositories/delorean.repo.md5
2025-11-26 07:46:15.505422 | controller | cd+++++++++ ci-framework-data/logs/
2025-11-26 07:46:15.505445 | controller | >f+++++++++ ci-framework-data/logs/ci_script_000_build_the_nat64_appliance.log
2025-11-26 07:46:15.505463 | controller | >f+++++++++ ci-framework-data/logs/ci_script_001_generate_nocloud_iso.log
2025-11-26 07:46:15.505479 | controller | >f+++++++++ ci-framework-data/logs/ci_script_002_generate_nocloud_iso.log
2025-11-26 07:46:15.505495 | controller | >f+++++++++ ci-framework-data/logs/hypervisor_info.log
2025-11-26 07:46:15.505510 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log
2025-11-26 07:46:15.505525 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_dns64_debug.log
2025-11-26 07:46:15.505540 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_journal.log
2025-11-26 07:46:15.505556 | controller | >f+++++++++ ci-framework-data/logs/nat64_appliance_node_info.log
2025-11-26 07:46:15.505571 | controller | >f+++++++++ ci-framework-data/logs/test_node_info.log
2025-11-26 07:46:15.505585 | controller | cd+++++++++ registries.conf.d/
2025-11-26 07:46:15.505600 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf
2025-11-26 07:46:15.505614 | controller | cd+++++++++ system-config/
2025-11-26 07:46:15.505629 | controller | cd+++++++++ system-config/libvirt/
2025-11-26 07:46:15.505645 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf
2025-11-26 07:46:15.505660 | controller | >f+++++++++ system-config/libvirt/libvirt.conf
2025-11-26 07:46:15.505674 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf
2025-11-26 07:46:15.505689 | controller | >f+++++++++ system-config/libvirt/network.conf
2025-11-26 07:46:15.505703 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf
2025-11-26 07:46:15.505717 | controller | >f+++++++++ system-config/libvirt/qemu.conf
2025-11-26 07:46:15.505731 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf
2025-11-26 07:46:15.505744 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf
2025-11-26 07:46:15.505758 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf
2025-11-26 07:46:15.505771 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf
2025-11-26 07:46:15.505785 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf
2025-11-26 07:46:15.505798 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf
2025-11-26 07:46:15.505811 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf
2025-11-26 07:46:15.505825 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf
2025-11-26 07:46:15.505838 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf
2025-11-26 07:46:15.505851 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf
2025-11-26 07:46:15.877370 | controller | changed: .d..t...... ./
2025-11-26 07:46:16.237061 | controller | changed: .d..t...... ./
2025-11-26 07:46:16.257606 | 
2025-11-26 07:46:16.257719 | TASK [Return artifact to Zuul]
2025-11-26 07:46:16.285921 | controller | ok
2025-11-26 07:46:16.304527 | 
2025-11-26 07:46:16.304593 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host]
2025-11-26 07:46:16.304694 | 
2025-11-26 07:46:16.304722 | PLAY RECAP
2025-11-26 07:46:16.304762 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1
2025-11-26 07:46:16.304783 | 
2025-11-26 07:46:16.385175 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main]
2025-11-26 07:46:16.385954 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-11-26 07:46:16.878503 | 
2025-11-26 07:46:16.878598 | PLAY [all]
2025-11-26 07:46:16.896763 | 
2025-11-26 07:46:16.896838 | TASK [include_role : fetch-output]
2025-11-26 07:46:16.925108 | controller | ok
2025-11-26 07:46:16.941202 | 
2025-11-26 07:46:16.941283 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-26 07:46:16.985173 | controller | skipping: Conditional result was False
2025-11-26 07:46:16.990572 | 
2025-11-26 07:46:16.990644 | TASK [fetch-output : Set log path for single node]
2025-11-26 07:46:17.018660 | controller | ok
2025-11-26 07:46:17.023501 | 
2025-11-26 07:46:17.023571 | LOOP [fetch-output : Ensure local output dirs]
2025-11-26 07:46:17.343664 | controller -> localhost | ok: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/logs"
2025-11-26 07:46:17.523475 | controller -> localhost | ok: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/artifacts"
2025-11-26 07:46:17.702364 | controller -> localhost | ok: "/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/docs"
2025-11-26 07:46:17.712981 | 
2025-11-26 07:46:17.713092 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-26 07:46:18.221640 | controller | ok
2025-11-26 07:46:18.221821 | controller | ok: All items complete
2025-11-26 07:46:18.221850 | 
2025-11-26 07:46:18.585001 | controller | ok
2025-11-26 07:46:18.952521 | controller | ok
2025-11-26 07:46:18.975913 | 
2025-11-26 07:46:18.976217 | TASK [include_role : fetch-output-openshift]
2025-11-26 07:46:18.993549 | controller | skipping: Conditional result was False
2025-11-26 07:46:19.001325 | 
2025-11-26 07:46:19.001465 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-26 07:46:19.344790 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006049
2025-11-26 07:46:19.535192 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006050
2025-11-26 07:46:19.563991 | 
2025-11-26 07:46:19.564102 | PLAY [all]
2025-11-26 07:46:19.577996 | 
2025-11-26 07:46:19.578080 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-11-26 07:46:19.972079 | controller | changed
2025-11-26 07:46:19.993500 | 
2025-11-26 07:46:19.993579 | PLAY RECAP
2025-11-26 07:46:19.993695 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-11-26 07:46:19.993723 | 
2025-11-26 07:46:20.062294 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-11-26 07:46:20.063040 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-11-26 07:46:20.601927 | 
2025-11-26 07:46:20.602046 | PLAY [localhost]
2025-11-26 07:46:20.619444 | 
2025-11-26 07:46:20.619542 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-26 07:46:20.921032 | localhost | changed
2025-11-26 07:46:20.925342 | 
2025-11-26 07:46:20.925443 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-26 07:46:20.943257 | localhost | ok
2025-11-26 07:46:20.950718 | 
2025-11-26 07:46:20.950787 | TASK [add-fileserver : Create SSH private key tempfile]
2025-11-26 07:46:21.251663 | localhost | changed
2025-11-26 07:46:21.257430 | 
2025-11-26 07:46:21.257515 | TASK [add-fileserver : Create SSH private key from secret]
2025-11-26 07:46:21.790838 | localhost | changed
2025-11-26 07:46:21.795570 | 
2025-11-26 07:46:21.795638 | TASK [add-fileserver : Add fileserver ssh key]
2025-11-26 07:46:22.126798 | localhost | Identity added: /var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/tmp/ansible.mxt22w2e (/var/lib/zuul/builds/04a778c41bbc4932ba83f3752f617298/work/tmp/ansible.mxt22w2e)
2025-11-26 07:46:22.126966 | localhost | ok: Runtime: 0:00:00.006028
2025-11-26 07:46:22.131130 | 
2025-11-26 07:46:22.131201 | TASK [add-fileserver : Remove SSH private key from disk]
2025-11-26 07:46:22.350480 | localhost | ok: Runtime: 0:00:00.004923
2025-11-26 07:46:22.354998 | 
2025-11-26 07:46:22.355077 | TASK [add-fileserver : Add fileserver to inventory]
2025-11-26 07:46:22.403684 | localhost | changed
2025-11-26 07:46:22.408532 | 
2025-11-26 07:46:22.408603 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-11-26 07:46:22.720087 | localhost | changed
2025-11-26 07:46:22.739604 | 
2025-11-26 07:46:22.739687 | PLAY [localhost]
2025-11-26 07:46:22.750895 | 
2025-11-26 07:46:22.750964 | TASK [Generate bulk log download script]
2025-11-26 07:46:22.769060 | localhost | ok
2025-11-26 07:46:22.780370 | 
2025-11-26 07:46:22.780476 | TASK [local-log-download : Check API endpoint is defined]
2025-11-26 07:46:22.807874 | localhost | ok: All assertions passed
2025-11-26 07:46:22.812178 | 
2025-11-26 07:46:22.812244 | TASK [local-log-download : Create download script]
2025-11-26 07:46:23.161591 | localhost -> localhost | changed
2025-11-26 07:46:23.170369 | 
2025-11-26 07:46:23.170471 | TASK [Register quick-download link]
2025-11-26 07:46:23.187431 | localhost | ok
2025-11-26 07:46:23.220678 | 
2025-11-26 07:46:23.220760 | PLAY [logserver.rdoproject.org]
2025-11-26 07:46:23.230117 | 
2025-11-26 07:46:23.230181 | TASK [Set zuul-log-path fact]
2025-11-26 07:46:23.245771 | logserver.rdoproject.org | ok
2025-11-26 07:46:23.254770 | 
2025-11-26 07:46:23.254837 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-26 07:46:23.280661 | logserver.rdoproject.org | ok
2025-11-26 07:46:23.286201 | 
2025-11-26 07:46:23.286266 | TASK [upload-logs : Create log directories]
2025-11-26 07:46:25.100629 | logserver.rdoproject.org | changed
2025-11-26 07:46:25.103581 | 
2025-11-26 07:46:25.103647 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-11-26 07:46:25.319575 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005056
2025-11-26 07:46:25.324032 | 
2025-11-26 07:46:25.324109 | TASK [upload-logs : Upload logs to log server]
2025-11-26 07:46:28.168763 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-11-26 07:46:28.171501 | 
2025-11-26 07:46:28.171567 | LOOP [upload-logs : Compress console log and json output]
2025-11-26 07:46:28.209946 | logserver.rdoproject.org | skipping: Conditional result was False
2025-11-26 07:46:28.217887 | logserver.rdoproject.org | skipping: Conditional result was False
2025-11-26 07:46:28.228606 | 
2025-11-26 07:46:28.228694 | LOOP [upload-logs : Upload compressed console log and json output]
2025-11-26 07:46:28.263827 | logserver.rdoproject.org | skipping: Conditional result was False
2025-11-26 07:46:28.264055 | 
2025-11-26 07:46:28.267145 | logserver.rdoproject.org | skipping: Conditional result was False
2025-11-26 07:46:28.275624 | 
2025-11-26 07:46:28.275707 | LOOP [upload-logs : Upload console log and json output]