2025-09-30 08:01:21.795225 | Job console starting... 2025-09-30 08:01:21.804035 | Updating repositories 2025-09-30 08:01:21.845301 | Preparing job workspace 2025-09-30 08:01:28.567423 | Running Ansible setup... 2025-09-30 08:01:35.762968 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 08:01:36.373521 | 2025-09-30 08:01:36.373641 | PLAY [localhost] 2025-09-30 08:01:36.382821 | 2025-09-30 08:01:36.382906 | TASK [Gathering Facts] 2025-09-30 08:01:37.304392 | localhost | ok 2025-09-30 08:01:37.320219 | 2025-09-30 08:01:37.320422 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-30 08:01:37.835568 | localhost -> localhost | changed 2025-09-30 08:01:37.841308 | 2025-09-30 08:01:37.841377 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-30 08:01:38.682925 | localhost -> localhost | changed 2025-09-30 08:01:38.701565 | 2025-09-30 08:01:38.701742 | TASK [Setup log path fact] 2025-09-30 08:01:38.740811 | localhost | ok 2025-09-30 08:01:38.757261 | 2025-09-30 08:01:38.757354 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 08:01:38.786887 | localhost | ok 2025-09-30 08:01:38.795744 | 2025-09-30 08:01:38.795819 | TASK [emit-job-header : Print job information] 2025-09-30 08:01:38.835009 | # Job Information 2025-09-30 08:01:38.835156 | Ansible Version: 2.15.12 2025-09-30 08:01:38.835183 | Job: cifmw-molecule-ci_multus 2025-09-30 08:01:38.835203 | Pipeline: github-check 2025-09-30 08:01:38.835221 | Executor: ze04.softwarefactory-project.io 2025-09-30 08:01:38.835242 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333 2025-09-30 08:01:38.835270 | Log URL (when completed): https://logserver.rdoproject.org/544/rdoproject.org/544f8b65120048bdb921b8e39f7a1ea3/ 2025-09-30 08:01:38.835300 | Event ID: 4f943a60-9dd3-11f0-8665-ec0281ef448c 2025-09-30 08:01:38.839401 | 2025-09-30 08:01:38.839466 | LOOP [emit-job-header : Print node information] 2025-09-30 08:01:38.938467 | localhost | ok: 2025-09-30 08:01:38.938659 | localhost | # Node Information 2025-09-30 08:01:38.938715 | localhost | Inventory Hostname: controller 2025-09-30 08:01:38.938746 | localhost | Hostname: np0005462021 2025-09-30 08:01:38.938775 | localhost | Username: zuul 2025-09-30 08:01:38.938803 | localhost | Distro: CentOS 9 2025-09-30 08:01:38.938826 | localhost | Provider: vexxhost-nodepool-tripleo 2025-09-30 08:01:38.938852 | localhost | Region: RegionOne 2025-09-30 08:01:38.938877 | localhost | Label: centos-9-stream-crc-2-48-0-xxl 2025-09-30 08:01:38.938903 | localhost | Product Name: OpenStack Nova 2025-09-30 08:01:38.938927 | localhost | Interface IP: 38.102.83.5 2025-09-30 08:01:38.965333 | 2025-09-30 08:01:38.965397 | PLAY [all] 2025-09-30 08:01:38.973120 | 2025-09-30 08:01:38.973204 | TASK [Gather network facts] 2025-09-30 08:01:39.581990 | controller | ok 2025-09-30 08:01:39.601268 | 2025-09-30 08:01:39.601345 | TASK [include_role : start-zuul-console] 2025-09-30 08:01:39.619839 | controller | ok 2025-09-30 08:01:39.640462 | 2025-09-30 08:01:39.641039 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-30 08:01:40.100275 | controller | ok 2025-09-30 08:01:40.114442 | 2025-09-30 08:01:40.114569 | TASK [include_role : add-build-sshkey] 2025-09-30 08:01:40.168941 | controller | ok 2025-09-30 08:01:40.194726 | 2025-09-30 08:01:40.194854 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-30 08:01:40.404850 | controller -> localhost | ok 2025-09-30 08:01:40.411742 | 2025-09-30 08:01:40.411812 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-30 08:01:40.442891 | controller | ok 2025-09-30 08:01:40.465735 | controller | included: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-30 08:01:40.472339 | 2025-09-30 08:01:40.472399 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-30 08:01:41.077670 | controller -> localhost | Generating public/private rsa key pair. 2025-09-30 08:01:41.077937 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/544f8b65120048bdb921b8e39f7a1ea3_id_rsa. 2025-09-30 08:01:41.077968 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/544f8b65120048bdb921b8e39f7a1ea3_id_rsa.pub. 2025-09-30 08:01:41.077990 | controller -> localhost | The key fingerprint is: 2025-09-30 08:01:41.078009 | controller -> localhost | SHA256:KTvCJfERRCZZrRwTvIII5xad5vvQRC+hMZNnsO66aSE zuul-build-sshkey 2025-09-30 08:01:41.078029 | controller -> localhost | The key's randomart image is: 2025-09-30 08:01:41.078047 | controller -> localhost | +---[RSA 3072]----+ 2025-09-30 08:01:41.078065 | controller -> localhost | | .oXBo | 2025-09-30 08:01:41.078083 | controller -> localhost | |. o X+O.. | 2025-09-30 08:01:41.078101 | controller -> localhost | |.+ =oX.B | 2025-09-30 08:01:41.078119 | controller -> localhost | |. +.+o*... | 2025-09-30 08:01:41.078168 | controller -> localhost | | . o=+.S | 2025-09-30 08:01:41.078192 | controller -> localhost | |E .ooo.o | 2025-09-30 08:01:41.078209 | controller -> localhost | | . .+oo | 2025-09-30 08:01:41.078229 | controller -> localhost | | .o ... | 2025-09-30 08:01:41.078247 | controller -> localhost | | .+. | 2025-09-30 08:01:41.078264 | controller -> localhost | +----[SHA256]-----+ 2025-09-30 08:01:41.078308 | controller -> localhost | ok: Runtime: 0:00:00.186486 2025-09-30 08:01:41.084067 | 2025-09-30 08:01:41.084132 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-30 08:01:41.103250 | controller | ok 2025-09-30 08:01:41.112621 | controller | included: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-30 08:01:41.121246 | 2025-09-30 08:01:41.121307 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-30 08:01:41.145212 | controller | skipping: Conditional result was False 2025-09-30 08:01:41.150491 | 2025-09-30 08:01:41.150553 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-30 08:01:41.755048 | controller | changed 2025-09-30 08:01:41.768085 | 2025-09-30 08:01:41.768254 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-30 08:01:42.151888 | controller | ok 2025-09-30 08:01:42.201907 | 2025-09-30 08:01:42.202917 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-30 08:01:43.980481 | controller | changed 2025-09-30 08:01:43.985763 | 2025-09-30 08:01:43.985828 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-30 08:01:45.601406 | controller | changed 2025-09-30 08:01:45.609170 | 2025-09-30 08:01:45.609271 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-30 08:01:45.635078 | controller | skipping: Conditional result was False 2025-09-30 08:01:45.645530 | 2025-09-30 08:01:45.645732 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-30 08:01:46.065536 | controller -> localhost | changed 2025-09-30 08:01:46.086249 | 2025-09-30 08:01:46.086391 | TASK [add-build-sshkey : Add back temp key] 2025-09-30 08:01:46.382062 | controller -> localhost | Identity added: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/544f8b65120048bdb921b8e39f7a1ea3_id_rsa (zuul-build-sshkey) 2025-09-30 08:01:46.382522 | controller -> localhost | ok: Runtime: 0:00:00.008639 2025-09-30 08:01:46.395257 | 2025-09-30 08:01:46.395389 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-30 08:01:46.819738 | controller | ok 2025-09-30 08:01:46.830143 | 2025-09-30 08:01:46.830301 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-30 08:01:46.858023 | controller | skipping: Conditional result was False 2025-09-30 08:01:46.878536 | 2025-09-30 08:01:46.878733 | TASK [include_role : validate-host] 2025-09-30 08:01:46.911774 | controller | ok 2025-09-30 08:01:46.961069 | 2025-09-30 08:01:46.961178 | TASK [validate-host : Define zuul_info_dir fact] 2025-09-30 08:01:46.991490 | controller | ok 2025-09-30 08:01:46.997776 | 2025-09-30 08:01:46.997861 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-09-30 08:01:47.297612 | controller -> localhost | ok 2025-09-30 08:01:47.303415 | 2025-09-30 08:01:47.303477 | TASK [validate-host : Collect information about the host] 2025-09-30 08:01:48.164344 | controller | ok 2025-09-30 08:01:48.184782 | 2025-09-30 08:01:48.184919 | TASK [validate-host : Sanitize hostname] 2025-09-30 08:01:48.263261 | controller | ok 2025-09-30 08:01:48.273830 | 2025-09-30 08:01:48.273964 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-09-30 08:01:48.815732 | controller -> localhost | changed 2025-09-30 08:01:48.828023 | 2025-09-30 08:01:48.828162 | TASK [validate-host : Collect information about zuul worker] 2025-09-30 08:01:49.375349 | controller | ok 2025-09-30 08:01:49.385988 | 2025-09-30 08:01:49.386147 | TASK [validate-host : Write out all zuul information for each host] 2025-09-30 08:01:49.902945 | controller -> localhost | changed 2025-09-30 08:01:49.924188 | 2025-09-30 08:01:49.924329 | TASK [include_role : prepare-workspace-openshift] 2025-09-30 08:01:49.940150 | controller | skipping: Conditional result was False 2025-09-30 08:01:49.951116 | 2025-09-30 08:01:49.951246 | TASK [include_role : remove-zuul-sshkey] 2025-09-30 08:01:49.966757 | controller | skipping: Conditional result was False 2025-09-30 08:01:49.979088 | 2025-09-30 08:01:49.979246 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 08:01:50.321182 | controller | ok: "logs" 2025-09-30 08:01:50.321591 | controller | ok: All items complete 2025-09-30 08:01:50.321651 | 2025-09-30 08:01:50.634936 | controller | ok: "artifacts" 2025-09-30 08:01:50.941874 | controller | ok: "docs" 2025-09-30 08:01:50.955979 | 2025-09-30 08:01:50.956115 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 08:01:51.316141 | controller | changed: "logs" 2025-09-30 08:01:51.604148 | controller | changed: "artifacts" 2025-09-30 08:01:51.969250 | controller | changed: "docs" 2025-09-30 08:01:52.022099 | 2025-09-30 08:01:52.022201 | PLAY RECAP 2025-09-30 08:01:52.022259 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-30 08:01:52.022296 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 08:01:52.022322 | 2025-09-30 08:01:52.176149 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 08:01:52.177741 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master] 2025-09-30 08:01:52.809264 | 2025-09-30 08:01:52.809382 | PLAY [all] 2025-09-30 08:01:52.831083 | 2025-09-30 08:01:52.831184 | TASK [mirror-info-fork : Set mirror_fqdn if not defined] 2025-09-30 08:01:52.922246 | controller | ok 2025-09-30 08:01:52.927389 | 2025-09-30 08:01:52.927465 | TASK [mirror-info-fork : Create /etc/ci] 2025-09-30 08:01:53.464777 | controller | changed 2025-09-30 08:01:53.470718 | 2025-09-30 08:01:53.470794 | TASK [mirror-info-fork : Install ci_mirror script] 2025-09-30 08:01:55.053588 | controller | changed 2025-09-30 08:01:55.076449 | 2025-09-30 08:01:55.076604 | LOOP [add-authorized-keys : Enable access via build key on all nodes] 2025-09-30 08:01:55.663164 | controller | changed: 2025-09-30 08:01:55.663336 | controller | { 2025-09-30 08:01:55.663368 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAABIwAAAQEA4Z/c9osaGGtU6X8fgELwfj/yayRurfcKA0HMFfdpPxev2dbwljysMuzoVp4OZmW1gvGtyYPSNRvnzgsaabPNKNo2ym5NToCP6UM+KSe93aln4BcM/24mXChYAbXJQ5Bqq/pIzsGs/pKetQN+vwvMxLOwTvpcsCJBXaa981RKML6xj9l/UZ7IIq1HSEKMvPLxZMWdu0Ut8DkCd5F4nOw9Wgml2uYpDCj5LLCrQQ9ChdOMz8hz6SighhNlRpPkvPaet3OXxr/ytFMu7j7vv06CaEnuMMiY2aTWN1Imin9eHAylIqFHta/3gFfQSWt9jXM7owkBLKL7ATzhaAn+fjNupw== arxcruz@redhat.com" 2025-09-30 08:01:55.663397 | controller | } 2025-09-30 08:01:56.095999 | controller | changed: 2025-09-30 08:01:56.096100 | controller | { 2025-09-30 08:01:56.096126 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDS4Fn6k4deCnIlOtLWqZJyksbepjQt04j8Ed8CGx9EKkj0fKiAxiI4TadXQYPuNHMixZy4Nevjb6aDhL5Z906TfvNHKUrjrG7G26a0k8vdc61NEQ7FmcGMWRLwwc6ReDO7lFpzYKBMk4YqfWgBuGU/K6WLKiVW2cVvwIuGIaYrE1OiiX0iVUUk7KApXlDJMXn7qjSYynfO4mF629NIp8FJal38+Kv+HA+0QkE5Y2xXnzD4Lar5+keymiCHRntPppXHeLIRzbt0gxC7v3L72hpQ3BTBEzwHpeS8KY+SX1y5lRMN45thCHfJqGmARJREDjBvWG8JXOPmVIKQtZmVcD5b mandreou@redhat.com" 2025-09-30 08:01:56.096146 | controller | } 2025-09-30 08:01:56.431078 | controller | changed: 2025-09-30 08:01:56.431181 | controller | { 2025-09-30 08:01:56.431204 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9MiLfy30deHA7xPOAlew5qUq3UP2gmRMYJi8PtkjFB20/DKeWwWNnkZPqP9AayruRoo51SIiVg870gbZE2jYl+Ncx/FYDe56JeC3ySZsXoAVkC9bP7gkOGqOmJjirvAgPMI7bogVz8i+66Q4Ar7OKTp3762G4IuWPPEg4ce4Y7lx9qWocZapHYq4cYKMxrOZ7SEbFSATBbe2bPZAPKTw8do/Eny+Hq/LkHFhIeyra6cqTFQYShr+zPln0Cr+ro/pDX3bB+1ubFgTpjpkkkQsLhDfR6cCdCWM2lgnS3BTtYj5Ct9/JRPR5YOphqZz+uB+OEu2IL68hmU9vNTth1KeX rlandy@redhat.com" 2025-09-30 08:01:56.431223 | controller | } 2025-09-30 08:01:56.782245 | controller | changed: 2025-09-30 08:01:56.782361 | controller | { 2025-09-30 08:01:56.782385 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIFCbgz8gdERiJlk2IKOtkjQxEXejrio6ZYMJAVJYpOIp raukadah@gmail.com" 2025-09-30 08:01:56.782404 | controller | } 2025-09-30 08:01:57.173845 | controller | changed: 2025-09-30 08:01:57.173953 | controller | { 2025-09-30 08:01:57.173976 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIBqb3Q/9uDf4LmihQ7xeJ9gA/STIQUFPSfyyV0m8AoQi bshewale@redhat.com" 2025-09-30 08:01:57.173994 | controller | } 2025-09-30 08:01:57.555231 | controller | changed: 2025-09-30 08:01:57.555344 | controller | { 2025-09-30 08:01:57.555383 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC0I8QqQx0Az2ysJt2JuffucLijhBqnsXKEIx5GyHwxVULROa8VtNFXUDH6ZKZavhiMcmfHB2+TBTda+lDP4FldYj06dGmzCY+IYGa+uDRdxHNGYjvCfLFcmLlzRK6fNbTcui+KlUFUdKe0fb9CRoGKyhlJD5GRkM1Dv+Yb6Bj+RNnmm1fVGYxzmrD2utvffYEb0SZGWxq2R9gefx1q/3wCGjeqvufEV+AskPhVGc5T7t9eyZ4qmslkLh1/nMuaIBFcr9AUACRajsvk6mXrAN1g3HlBf2gQlhi1UEyfbqIQvzzFtsbLDlSum/KmKjy818GzvWjERfQ0VkGzCd9bSLVL dviroel@redhat.com" 2025-09-30 08:01:57.555404 | controller | } 2025-09-30 08:01:57.964762 | controller | changed: 2025-09-30 08:01:57.964862 | controller | { 2025-09-30 08:01:57.964884 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDLOQd4ZLtkZXQGY6UwAr/06ppWQK4fDO3HaqxPk98csyOCBXsliSKK39Bso828+5srIXiW7aI6aC9P5mwi4mUZlGPfJlQbfrcGvY+b/SocuvaGK+1RrHLoJCT52LBhwgrzlXio2jeksZeein8iaTrhsPrOAs7KggIL/rB9hEiB3NaOPWhhoCP4vlW6MEMExGcqB/1FVxXFBPnLkEyW0Lk7ycVflZl2ocRxbfjZi0+tI1Wlinp8PvSQSc/WVrAcDgKjc/mB4ODPOyYy3G8FHgfMsrXSDEyjBKgLKMsdCrAUcqJQWjkqXleXSYOV4q3pzL+9umK+q/e3P/bIoSFQzmJKTU1eDfuvPXmow9F5H54fii/Da7ezlMJ+wPGHJrRAkmzvMbALy7xwswLhZMkOGNtRcPqaKYRmIBKpw3o6bCTtcNUHOtOQnzwY8JzrM2eBWJBXAANYw+9/ho80JIiwhg29CFNpVBuHbql2YxJQNrnl90guN65rYNpDxdIluweyUf8= anbanerj@kaermorhen" 2025-09-30 08:01:57.964903 | controller | } 2025-09-30 08:01:58.400302 | controller | changed: 2025-09-30 08:01:58.400399 | controller | { 2025-09-30 08:01:58.400423 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQC3VwV8Im9kRm49lt3tM36hj4Zv27FxGo4C1Q/0jqhzFmHY7RHbmeRr8ObhwWoHjXSozKWg8FL5ER0z3hTwL0W6lez3sL7hUaCmSuZmG5Hnl3x4vTSxDI9JZ/Y65rtYiiWQo2fC5xJhU/4+0e5e/pseCm8cKRSu+SaxhO+sd6FDojA2x1BzOzKiQRDy/1zWGp/cZkxcEuB1wHI5LMzN03c67vmbu+fhZRAUO4dQkvcnj2LrhQtpa+ytvnSjr8icMDosf1OsbSffwZFyHB/hfWGAfe0eIeSA2XPraxiPknXxiPKx2MJsaUTYbsZcm3EjFdHBBMumw5rBI74zLrMRvCO9GwBEmGT4rFng1nP+yw5DB8sn2zqpOsPg1LYRwCPOUveC13P6pgsZZPh812e8v5EKnETct+5XI3dVpdw6CnNiLwAyVAF15DJvBGT/u1k0Myg/bQn+Gv9k2MSj6LvQmf6WbZu2Wgjm30z3FyCneBqTL7mLF19YXzeC0ufHz5pnO1E= dasm@fedora" 2025-09-30 08:01:58.400441 | controller | } 2025-09-30 08:01:58.763545 | controller | changed: 2025-09-30 08:01:58.763674 | controller | { 2025-09-30 08:01:58.763714 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIHUnwjB20UKmsSed9X73eGNV5AOEFccQ3NYrRW776pEk cjeanner" 2025-09-30 08:01:58.763741 | controller | } 2025-09-30 08:01:59.131122 | controller | changed: 2025-09-30 08:01:59.131383 | controller | { 2025-09-30 08:01:59.131417 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDercCMGn8rW1C4P67tHgtflPdTeXlpyUJYH+6XDd2lR jgilaber@redhat.com" 2025-09-30 08:01:59.131436 | controller | } 2025-09-30 08:01:59.589674 | controller | changed: 2025-09-30 08:01:59.589793 | controller | { 2025-09-30 08:01:59.589816 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIAMI6kkg9Wg0sG7jIJmyZemEBwUn1yzNpQQd3gnulOmZ adrianfuscoarnejo@gmail.com" 2025-09-30 08:01:59.589835 | controller | } 2025-09-30 08:02:00.015871 | controller | changed: 2025-09-30 08:02:00.015983 | controller | { 2025-09-30 08:02:00.016015 | controller | "public_key": "ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPijwpQu/3jhhhBZInXNOLEH57DrknPc3PLbsRvYyJIFzwYjX+WD4a7+nGnMYS42MuZk6TJcVqgnqofVx4isoD4= ramishra@redhat.com" 2025-09-30 08:02:00.016041 | controller | } 2025-09-30 08:02:00.427561 | controller | changed: 2025-09-30 08:02:00.427671 | controller | { 2025-09-30 08:02:00.427715 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIGpU/BepK3qX0NRf5Np+dOBDqzQEefhNrw2DCZaH3uWW rebtoor@monolith" 2025-09-30 08:02:00.427735 | controller | } 2025-09-30 08:02:00.855659 | controller | changed: 2025-09-30 08:02:00.855771 | controller | { 2025-09-30 08:02:00.855795 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDK0iKdi8jQTpQrDdLVH/AAgLVYyTXF7AQ1gjc/5uT3t ykarel@yatinkarel" 2025-09-30 08:02:00.855813 | controller | } 2025-09-30 08:02:01.338569 | controller | changed: 2025-09-30 08:02:01.338764 | controller | { 2025-09-30 08:02:01.338801 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIF/V/cLotA6LZeO32VL45Hd78skuA2lJA425Sm2LlQeZ fmount@horcrux" 2025-09-30 08:02:01.338822 | controller | } 2025-09-30 08:02:01.756969 | controller | changed: 2025-09-30 08:02:01.757247 | controller | { 2025-09-30 08:02:01.757327 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIDa7QCjuDMVmRPo1rREbGwzYeBCYVN+Ou/3WKXZEC6Sr" 2025-09-30 08:02:01.757389 | controller | } 2025-09-30 08:02:02.158934 | controller | changed: 2025-09-30 08:02:02.159047 | controller | { 2025-09-30 08:02:02.159080 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCfNtF7NvKl915TGsGGoseUb06Hj8L/S4toWf0hExeY+F00woL6NvBlJD0nDct+P5a22I4EhvoQCRQ8reaPCm1lybR3uiRIJsj+8zkVvLwby9LXzfZorlNG9ofjd00FEmB09uW/YvTl6Q9XwwwX6tInzIOv3TMqTHHGOL74ibbj8J/FJR0cFEyj0z4WQRvtkh32xAHl83gbuINryMt0sqRI+clj2381NKL55DRLQrVw0gsfqqxiHAnXg21qWmc4J+b9e9kiuAFQjcjwTVkwJCcg3xbPwC/qokYRby/Y5S40UUd7/jEARGXT7RZgpzTuDd1oZiCVrnrqJNPaMNdVv5MLeFdf1B7iIe5aa/fGouX7AO4SdKhZUdnJmCFAGvjC6S3JMZ2wAcUl+OHnssfmdj7XL50cLo27vjuzMtLAgSqi6N99m92WCF2s8J9aVzszX7Xz9OKZCeGsiVJp3/NdABKzSEAyM9xBD/5Vho894Sav+otpySHe3p6RUTgbB5Zu8VyZRZ/UtB3ueXxyo764yrc6qWIDqrehm84Xm9g+/jpIBzGPl07NUNJpdt/6Sgf9RIKXw/7XypO5yZfUcuFNGTxLfqjTNrtgLZNcjfav6sSdVXVcMPL//XNuRdKmVFaO76eV/oGMQGr1fGcCD+N+CpI7+Q+fCNB6VFWG4nZFuI/Iuw== averdagu@redhat.com" 2025-09-30 08:02:02.159106 | controller | } 2025-09-30 08:02:02.554596 | controller | changed: 2025-09-30 08:02:02.554773 | controller | { 2025-09-30 08:02:02.554830 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDq8l27xI+QlQVdS4djp9ogSoyrNE2+Ox6vKPdhSNL1J3PE5w+WCSvMz9A5gnNuH810zwbekEApbxTze/gLQJwBHA52CChfURpXrFaxY7ePXRElwKAL3mJfzBWY/c5jnNL9TCVmFJTGZkFZP3Nh+BMgZvL6xBkt3WKm6Uq18qzd9XeKcZusrA+O+uLv1fVeQnadY9RIqOCyeFYCzLWrUfTyE8x/XG0hAWIM7qpnF2cALQS2h9n4hW5ybiUN790H08wf9hFwEf5nxY9Z9dVkPFQiTSGKNBzmnCXU9skxS/xhpFjJ5duGSZdtAHe9O+nGZm9c67hxgtf8e5PDuqAdXEv2cf6e3VBAt+Bz8EKI3yosTj0oZHfwr42Yzb1l/SKy14Rggsrc9KAQlrGXan6+u2jcQqqx7l+SWmnpFiWTV9u5cWj2IgOhApOitmRBPYqk9rE2usfO0hLn/Pj/R/Nau4803e1/EikdLE7Ps95s9mX5jRDjAoUa2JwFF5RsVFyL910= ashigupt@ashigupt.remote.csb" 2025-09-30 08:02:02.554874 | controller | } 2025-09-30 08:02:02.955310 | controller | changed: 2025-09-30 08:02:02.955448 | controller | { 2025-09-30 08:02:02.955499 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOKLl0NYKwoZ/JY5KeZU8VwRAggeOxqQJeoqp3dsAaY9" 2025-09-30 08:02:02.955540 | controller | } 2025-09-30 08:02:03.380219 | controller | changed: 2025-09-30 08:02:03.380357 | controller | { 2025-09-30 08:02:03.380407 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIASASQOH2BcOyLKuuDOdWZlPi2orcjcA8q4400T73DLH evallesp@fedora" 2025-09-30 08:02:03.380448 | controller | } 2025-09-30 08:02:03.766161 | controller | changed: 2025-09-30 08:02:03.766300 | controller | { 2025-09-30 08:02:03.766371 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAILeBWlamUph+jRKV2qrx1PGU7vWuGIt5+z9k96I8WehW amsinha@amsinha-mac" 2025-09-30 08:02:03.766420 | controller | } 2025-09-30 08:02:04.172156 | controller | changed: 2025-09-30 08:02:04.172262 | controller | { 2025-09-30 08:02:04.172285 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIANvVgvJBlK3gb1yz5uef/JqIGq4HLEmY2dYA8e37swb morenod@redhat-laptop" 2025-09-30 08:02:04.172303 | controller | } 2025-09-30 08:02:04.569180 | controller | changed: 2025-09-30 08:02:04.569517 | controller | { 2025-09-30 08:02:04.569579 | controller | "public_key": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQDZdI7t1cxYx65heVI24HTV4F7oQLW1zyfxHreL2TIJKxjyrUUKIFEUmTutcBlJRLNT2Eoix6x1sOw9YrchloCLcn//SGfTElr9mSc5jbjb7QXEU+zJMhtxyEJ1Po3CUGnj7ckiIXw7wcawZtrEOAQ9pH3ExYCJcEMiyNjRQZCxT3tPK+S4B95EWh5Fsrz9CkwpjNRPPH7LigCeQTM3Wc7r97utAslBUUvYceDSLA7rMgkitJE38b7rZBeYzsGQ8YYUBjTCtehqQXxCRjizbHWaaZkBU+N3zkKB6n/iCNGIO690NK7A/qb6msTijiz1PeuM8ThOsi9qXnbX5v0PoTpcFSojV7NHAQ71f0XXuS43FhZctT+Dcx44dT8Fb5vJu2cJGrk+qF8ZgJYNpRS7gPg0EG2EqjK7JMf9ULdjSu0r+KlqIAyLvtzT4eOnQipoKlb/WG5D/0ohKv7OMQ352ggfkBFIQsRXyyTCT98Ft9juqPuahi3CAQmP4H9dyE+7+Kz437PEtsxLmfm6naNmWi7Ee1DqWPwS8rEajsm4sNM4wW9gdBboJQtc0uZw0DfLj1I9r3Mc8Ol0jYtz0yNQDSzVLrGCaJlC311trU70tZ+ZkAVV6Mn8lOhSbj1cK0lvSr6ZK4dgqGl3I1eTZJJhbLNdg7UOVaiRx9543+C/p/As7w== brjackma@redhat.com" 2025-09-30 08:02:04.569622 | controller | } 2025-09-30 08:02:04.942864 | controller | changed: 2025-09-30 08:02:04.942968 | controller | { 2025-09-30 08:02:04.942992 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIKwedoZ0TWPJX/z/4TAbO/kKcDZOQVgRH0hAqrL5UCI1 vcastell@redhat.com" 2025-09-30 08:02:04.943010 | controller | } 2025-09-30 08:02:05.300249 | controller | changed: 2025-09-30 08:02:05.300353 | controller | { 2025-09-30 08:02:05.300378 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIEmv8sE8GCk6ZTPIqF0FQrttBdL3mq7rCm/IJy0xDFh7 michburk@redhat.com" 2025-09-30 08:02:05.300399 | controller | } 2025-09-30 08:02:05.681351 | controller | changed: 2025-09-30 08:02:05.681449 | controller | { 2025-09-30 08:02:05.681471 | controller | "public_key": "ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICy6GpGEtwevXEEn4mmLR5lmSLe23dGgAvzkB9DMNbkf rsafrono@rsafrono" 2025-09-30 08:02:05.681489 | controller | } 2025-09-30 08:02:05.702970 | 2025-09-30 08:02:05.703085 | TASK [Set timezone to UTC] 2025-09-30 08:02:06.430097 | controller | changed: executed `/bin/timedatectl set-timezone UTC` 2025-09-30 08:02:06.449974 | 2025-09-30 08:02:06.450161 | TASK [Create nodepool directory] 2025-09-30 08:02:06.838793 | controller | changed 2025-09-30 08:02:06.852442 | 2025-09-30 08:02:06.852762 | TASK [Create nodepool sub_nodes file] 2025-09-30 08:02:08.224891 | controller | changed 2025-09-30 08:02:08.239839 | 2025-09-30 08:02:08.240001 | TASK [Create nodepool sub_nodes_private file] 2025-09-30 08:02:09.573887 | controller | changed 2025-09-30 08:02:09.588027 | 2025-09-30 08:02:09.588211 | LOOP [Populate nodepool sub_nodes file] 2025-09-30 08:02:09.630401 | 2025-09-30 08:02:09.630647 | LOOP [Populate nodepool sub_nodes_private file] 2025-09-30 08:02:09.671337 | 2025-09-30 08:02:09.671728 | TASK [Create nodepool primary file] 2025-09-30 08:02:09.699132 | controller | skipping: Conditional result was False 2025-09-30 08:02:09.712560 | 2025-09-30 08:02:09.712873 | TASK [Create nodepool node_private for this node] 2025-09-30 08:02:11.017395 | controller | changed 2025-09-30 08:02:11.022997 | 2025-09-30 08:02:11.023059 | LOOP [Copy ssh keys to nodepool directory] 2025-09-30 08:02:11.506729 | controller | ok: Item: id_rsa Runtime: 0:00:00.008430 2025-09-30 08:02:11.507112 | 2025-09-30 08:02:11.782947 | controller | ok: Item: id_rsa.pub Runtime: 0:00:00.006770 2025-09-30 08:02:11.802626 | 2025-09-30 08:02:11.802821 | TASK [Add sudoers role for zuul-sudo-grep.sh] 2025-09-30 08:02:13.301290 | controller | changed 2025-09-30 08:02:13.314210 | 2025-09-30 08:02:13.314359 | TASK [Validate sudoers config after edits] 2025-09-30 08:02:13.754813 | controller | /etc/sudoers: parsed OK 2025-09-30 08:02:13.754931 | controller | /etc/sudoers.d/90-cloud-init-users: parsed OK 2025-09-30 08:02:13.754941 | controller | /etc/sudoers.d/zuul: parsed OK 2025-09-30 08:02:13.754948 | controller | /etc/sudoers.d/zuul-sudo-grep: parsed OK 2025-09-30 08:02:13.870302 | controller | ok: Runtime: 0:00:00.009211 2025-09-30 08:02:13.882576 | 2025-09-30 08:02:13.882761 | TASK [Show the environment passed in to job shell scripts] 2025-09-30 08:02:14.251091 | controller | SHELL=/bin/bash 2025-09-30 08:02:14.251140 | controller | ZUUL_PROJECT=openstack-k8s-operators/ci-framework 2025-09-30 08:02:14.251158 | controller | ZUUL_SHORT_PROJECT_NAME=ci-framework 2025-09-30 08:02:14.251166 | controller | ZUUL_CHANGES=openstack-k8s-operators/ci-framework:main:refs/changes/46/3346/eb5b53fb17db92a72d33d052a56c8edd0d10ea78^openstack-k8s-operators/ci-framework:main:refs/changes/52/3352/6442e37e2e901d750c5bf184fc25fe0337bd2e95^openstack-k8s-operators/ci-framework:main:refs/changes/33/3333/b461fc761ffaeed72eedc04b84a1fb92d251fe5d 2025-09-30 08:02:14.251174 | controller | PWD=/home/zuul 2025-09-30 08:02:14.251181 | controller | ZUUL_PIPELINE=github-check 2025-09-30 08:02:14.251189 | controller | LOGNAME=zuul 2025-09-30 08:02:14.251196 | controller | XDG_SESSION_TYPE=tty 2025-09-30 08:02:14.251203 | controller | _=/usr/bin/env 2025-09-30 08:02:14.251210 | controller | MOTD_SHOWN=pam 2025-09-30 08:02:14.251217 | controller | HOME=/home/zuul 2025-09-30 08:02:14.251224 | controller | LANG=en_US.UTF-8 2025-09-30 08:02:14.251231 | controller | SSH_CONNECTION=38.102.83.114 37012 38.102.83.5 22 2025-09-30 08:02:14.251239 | controller | TOX_TESTENV_PASSENV=ZUUL_UUID ZUUL_PROJECT ZUUL_SHORT_PROJECT_NAME ZUUL_PIPELINE ZUUL_VOTING WORKSPACE BUILD_TIMEOUT ZUUL_BRANCH ZUUL_CHANGES ZUUL_CHANGE_IDS ZUUL_CHANGE ZUUL_PATCHSET 2025-09-30 08:02:14.251250 | controller | ZUUL_CHANGE_IDS=3346,eb5b53fb17db92a72d33d052a56c8edd0d10ea78 3352,6442e37e2e901d750c5bf184fc25fe0337bd2e95 3333,b461fc761ffaeed72eedc04b84a1fb92d251fe5d 2025-09-30 08:02:14.251258 | controller | WORKSPACE=/home/zuul/workspace 2025-09-30 08:02:14.251265 | controller | XDG_SESSION_CLASS=user 2025-09-30 08:02:14.251273 | controller | SELINUX_ROLE_REQUESTED= 2025-09-30 08:02:14.251281 | controller | LESSOPEN=||/usr/bin/lesspipe.sh %s 2025-09-30 08:02:14.251288 | controller | USER=zuul 2025-09-30 08:02:14.251296 | controller | ZUUL_VOTING=True 2025-09-30 08:02:14.251303 | controller | BUILD_TIMEOUT=1800000 2025-09-30 08:02:14.251311 | controller | SELINUX_USE_CURRENT_RANGE= 2025-09-30 08:02:14.251317 | controller | SHLVL=1 2025-09-30 08:02:14.251325 | controller | ZUUL_PATCHSET=b461fc761ffaeed72eedc04b84a1fb92d251fe5d 2025-09-30 08:02:14.251427 | controller | XDG_SESSION_ID=1 2025-09-30 08:02:14.251449 | controller | ZUUL_BRANCH=main 2025-09-30 08:02:14.251464 | controller | XDG_RUNTIME_DIR=/run/user/1000 2025-09-30 08:02:14.251471 | controller | SSH_CLIENT=38.102.83.114 37012 22 2025-09-30 08:02:14.251479 | controller | DEBUGINFOD_URLS=https://debuginfod.centos.org/ 2025-09-30 08:02:14.251487 | controller | DEBUGINFOD_IMA_CERT_PATH=/etc/keys/ima: 2025-09-30 08:02:14.251494 | controller | which_declare=declare -f 2025-09-30 08:02:14.251503 | controller | PATH=/home/zuul/.crc/bin/oc:/home/zuul/.local/bin:/home/zuul/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin 2025-09-30 08:02:14.251510 | controller | SELINUX_LEVEL_REQUESTED= 2025-09-30 08:02:14.251518 | controller | ZUUL_CHANGE=3333 2025-09-30 08:02:14.251525 | controller | DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus 2025-09-30 08:02:14.251532 | controller | ZUUL_UUID=544f8b65120048bdb921b8e39f7a1ea3 2025-09-30 08:02:14.251539 | controller | BASH_FUNC_which%%=() { ( alias; 2025-09-30 08:02:14.251549 | controller | eval ${which_declare} ) | /usr/bin/which --tty-only --read-alias --read-functions --show-tilde --show-dot $@ 2025-09-30 08:02:14.251555 | controller | } 2025-09-30 08:02:14.437113 | controller | ok: Runtime: 0:00:00.006781 2025-09-30 08:02:14.450439 | 2025-09-30 08:02:14.450576 | TASK [Workaround hardcoded /home/zuul/workspace in zuul_legacy_vars] 2025-09-30 08:02:14.478211 | controller | skipping: Conditional result was False 2025-09-30 08:02:14.491275 | 2025-09-30 08:02:14.491414 | TASK [Symlink /home/zuul-worker/workspace] 2025-09-30 08:02:15.089337 | controller | skipping: Conditional result was False 2025-09-30 08:02:15.095386 | 2025-09-30 08:02:15.095457 | TASK [Ensure legacy workspace directory] 2025-09-30 08:02:15.468768 | controller | changed 2025-09-30 08:02:15.511437 | 2025-09-30 08:02:15.511620 | PLAY RECAP 2025-09-30 08:02:15.511746 | controller | ok: 14 changed: 11 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-30 08:02:15.511801 | 2025-09-30 08:02:15.636946 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/pre.yaml@master] 2025-09-30 08:02:15.637750 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/crc/podman.yaml@master] 2025-09-30 08:02:16.216800 | 2025-09-30 08:02:16.216907 | PLAY [all,!compute] 2025-09-30 08:02:16.236421 | 2025-09-30 08:02:16.236507 | TASK [Enable container-tools rhel-modules for c8/crc node] 2025-09-30 08:02:16.766201 | controller | skipping: Conditional result was False 2025-09-30 08:02:16.779363 | 2025-09-30 08:02:16.779536 | TASK [Install podman] 2025-09-30 08:02:16.847349 | controller | skipping: Conditional result was False 2025-09-30 08:02:16.860219 | 2025-09-30 08:02:16.860358 | TASK [Set var name for quay login zuul secret] 2025-09-30 08:02:16.917715 | controller | skipping: Conditional result was False 2025-09-30 08:02:16.931351 | 2025-09-30 08:02:16.931494 | TASK [Print the username] 2025-09-30 08:02:17.482524 | controller | skipping: Conditional result was False 2025-09-30 08:02:17.490795 | 2025-09-30 08:02:17.490887 | TASK [Fail when user or password is not set] 2025-09-30 08:02:17.556165 | controller | skipping: Conditional result was False 2025-09-30 08:02:17.565009 | 2025-09-30 08:02:17.565100 | TASK [Set vars for quay login] 2025-09-30 08:02:17.622847 | 2025-09-30 08:02:17.623119 | LOOP [Perform container registry login(s) with podman] 2025-09-30 08:02:17.678188 | 2025-09-30 08:02:17.678364 | LOOP [Perform container registry login(s) with buildah] 2025-09-30 08:02:17.724014 | 2025-09-30 08:02:17.724219 | TASK [Set Insecure registry for content provider] 2025-09-30 08:02:17.759120 | controller | skipping: Conditional result was False 2025-09-30 08:02:17.780644 | 2025-09-30 08:02:17.780743 | PLAY RECAP 2025-09-30 08:02:17.780789 | controller | ok: 0 changed: 0 unreachable: 0 failed: 0 skipped: 9 rescued: 0 ignored: 0 2025-09-30 08:02:17.780811 | 2025-09-30 08:02:17.877074 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/crc/podman.yaml@master] 2025-09-30 08:02:17.877988 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/crc/simple-start.yaml@master] 2025-09-30 08:02:18.474636 | 2025-09-30 08:02:18.474772 | PLAY [Prefer ipv4 over ipv6] 2025-09-30 08:02:18.495037 | 2025-09-30 08:02:18.495188 | TASK [Configure /etc/gai.conf to prever ipv4 over ipv6] 2025-09-30 08:02:18.559846 | controller | skipping: Conditional result was False 2025-09-30 08:02:18.580665 | 2025-09-30 08:02:18.580771 | PLAY [controller] 2025-09-30 08:02:18.595374 | 2025-09-30 08:02:18.595461 | TASK [Fail when openshift_pull_sec not provided] 2025-09-30 08:02:18.619005 | controller | skipping: Conditional result was False 2025-09-30 08:02:18.625422 | 2025-09-30 08:02:18.625487 | TASK [Clone repos in the job workspace] 2025-09-30 08:02:18.644453 | controller | ok 2025-09-30 08:02:18.660425 | 2025-09-30 08:02:18.660493 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-30 08:02:19.144820 | controller | ok 2025-09-30 08:02:19.151434 | 2025-09-30 08:02:19.151499 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-30 08:02:22.347466 | controller | Output suppressed because no_log was given 2025-09-30 08:02:22.371166 | 2025-09-30 08:02:22.371304 | TASK [Create pull-secret.txt file] 2025-09-30 08:02:23.899942 | controller | Output suppressed because no_log was given 2025-09-30 08:02:23.913603 | 2025-09-30 08:02:23.913774 | TASK [Apply CRC features and print image build date] 2025-09-30 08:02:23.946665 | controller | ok 2025-09-30 08:02:23.964243 | controller | included: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/trusted/project_0/review.rdoproject.org/config/playbooks/crc/features.yaml 2025-09-30 08:02:23.976084 | 2025-09-30 08:02:23.976185 | TASK [Set additional parameters for crc - telemetry] 2025-09-30 08:02:24.550197 | controller | skipping: Conditional result was False 2025-09-30 08:02:24.563074 | 2025-09-30 08:02:24.563212 | TASK [Set additional parameters for crc - monitoring] 2025-09-30 08:02:25.116734 | controller | skipping: Conditional result was False 2025-09-30 08:02:25.129085 | 2025-09-30 08:02:25.129242 | TASK [Set minimum required memory to run the CRC when monitoring enabled] 2025-09-30 08:02:25.700628 | controller | skipping: Conditional result was False 2025-09-30 08:02:25.715042 | 2025-09-30 08:02:25.715344 | TASK [Set additional parameters for crc - enable microshift preset] 2025-09-30 08:02:26.270648 | controller | skipping: Conditional result was False 2025-09-30 08:02:26.279355 | 2025-09-30 08:02:26.279451 | TASK [Set additional parameters for crc - enable okd preset] 2025-09-30 08:02:26.821598 | controller | skipping: Conditional result was False 2025-09-30 08:02:26.829155 | 2025-09-30 08:02:26.829308 | TASK [Delete the cluster if there's a non-default bundle URL] 2025-09-30 08:02:27.365645 | controller | skipping: Conditional result was False 2025-09-30 08:02:27.378276 | 2025-09-30 08:02:27.378416 | TASK [Execute crc start command] 2025-09-30 08:05:39.187418 | controller | ok: Runtime: 0:03:10.851973 2025-09-30 08:05:39.199965 | 2025-09-30 08:05:39.200117 | TASK [Verify that OpenShift is up and running] 2025-09-30 08:05:39.229601 | controller | ok 2025-09-30 08:05:39.251057 | controller | included: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/trusted/project_0/review.rdoproject.org/config/playbooks/crc/verify_openshift_start.yaml 2025-09-30 08:05:39.261799 | 2025-09-30 08:05:39.261898 | TASK [Create script to login and verify services] 2025-09-30 08:05:40.588143 | controller | changed 2025-09-30 08:05:40.600546 | 2025-09-30 08:05:40.600711 | TASK [Ensure that user is logged] 2025-09-30 08:05:41.017044 | controller | Checking login to the cluster 1... 2025-09-30 08:05:41.932769 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:05:41.984944 | controller | 2025-09-30 08:05:41.985034 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:05:41.994667 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:05:47.001084 | controller | Checking login to the cluster 2... 2025-09-30 08:05:47.115581 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:05:47.135155 | controller | 2025-09-30 08:05:47.135237 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:05:47.140689 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:05:52.142698 | controller | Checking login to the cluster 3... 2025-09-30 08:05:52.267375 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:05:52.284327 | controller | 2025-09-30 08:05:52.284430 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:05:52.288920 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:05:57.292185 | controller | Checking login to the cluster 4... 2025-09-30 08:05:57.450322 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:05:57.482791 | controller | 2025-09-30 08:05:57.482866 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:05:57.488493 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:02.492581 | controller | Checking login to the cluster 5... 2025-09-30 08:06:02.643805 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:02.679868 | controller | 2025-09-30 08:06:02.679947 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:02.685257 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:07.688842 | controller | Checking login to the cluster 6... 2025-09-30 08:06:07.846084 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:07.954075 | controller | 2025-09-30 08:06:07.954200 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:07.961419 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:12.964430 | controller | Checking login to the cluster 7... 2025-09-30 08:06:13.832048 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:14.850314 | controller | 2025-09-30 08:06:14.850418 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:14.855084 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:19.857794 | controller | Checking login to the cluster 8... 2025-09-30 08:06:20.124873 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:20.411118 | controller | 2025-09-30 08:06:20.411202 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:20.415647 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:25.419988 | controller | Checking login to the cluster 9... 2025-09-30 08:06:25.905805 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:26.246752 | controller | 2025-09-30 08:06:26.246816 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:26.253087 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:31.257096 | controller | Checking login to the cluster 10... 2025-09-30 08:06:31.470013 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:31.554419 | controller | 2025-09-30 08:06:31.554498 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:06:31.558989 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:36.562874 | controller | Checking login to the cluster 11... 2025-09-30 08:06:36.755980 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:36.921108 | controller | 2025-09-30 08:06:36.921180 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:06:36.927283 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:41.930303 | controller | Checking login to the cluster 12... 2025-09-30 08:06:42.178548 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:42.344982 | controller | 2025-09-30 08:06:42.345090 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:06:42.352027 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:47.355739 | controller | Checking login to the cluster 13... 2025-09-30 08:06:47.531111 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:47.627149 | controller | 2025-09-30 08:06:47.627232 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:06:47.633090 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:06:52.635577 | controller | Checking login to the cluster 14... 2025-09-30 08:06:53.802798 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:06:55.487955 | controller | 2025-09-30 08:06:55.488024 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:06:55.493374 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:00.495958 | controller | Checking login to the cluster 15... 2025-09-30 08:07:01.317897 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:02.217072 | controller | 2025-09-30 08:07:02.217150 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:07:02.222567 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:07.226957 | controller | Checking login to the cluster 16... 2025-09-30 08:07:07.413701 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:07.602119 | controller | 2025-09-30 08:07:07.602210 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:07:07.608695 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:12.611206 | controller | Checking login to the cluster 17... 2025-09-30 08:07:12.774889 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:12.913891 | controller | 2025-09-30 08:07:12.913970 | controller | Error from server (InternalError): Internal error occurred: unexpected response: 503 2025-09-30 08:07:12.918440 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:17.921029 | controller | Checking login to the cluster 18... 2025-09-30 08:07:18.105540 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:18.160864 | controller | 2025-09-30 08:07:18.160938 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:07:18.166087 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:23.170243 | controller | Checking login to the cluster 19... 2025-09-30 08:07:23.360461 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:23.413661 | controller | 2025-09-30 08:07:23.413751 | controller | The connection to the server oauth-openshift.apps-crc.testing was refused - did you specify the right host or port? 2025-09-30 08:07:23.419200 | controller | Can not login to the CRC cluster. Sleeping... 2025-09-30 08:07:28.421472 | controller | Checking login to the cluster 20... 2025-09-30 08:07:28.591865 | controller | WARNING: Using insecure TLS client config. Setting this option is not supported! 2025-09-30 08:07:29.941210 | controller | 2025-09-30 08:07:29.941312 | controller | Login successful. 2025-09-30 08:07:30.033019 | controller | 2025-09-30 08:07:30.033116 | controller | You have access to 65 projects, the list has been suppressed. You can list all projects with 'oc projects' 2025-09-30 08:07:30.098712 | controller | 2025-09-30 08:07:30.098789 | controller | Using project "default". 2025-09-30 08:07:30.321329 | controller | changed 2025-09-30 08:07:30.336891 | 2025-09-30 08:07:30.337077 | TASK [Delete all openshift-marketplace pods] 2025-09-30 08:07:31.776038 | controller | pod "certified-operators-f8szs" deleted 2025-09-30 08:07:31.811441 | controller | pod "certified-operators-rvplv" deleted 2025-09-30 08:07:31.839942 | controller | pod "community-operators-5bfsp" deleted 2025-09-30 08:07:31.878856 | controller | pod "community-operators-5zsqg" deleted 2025-09-30 08:07:31.915125 | controller | pod "marketplace-operator-79b997595-d2lpl" deleted 2025-09-30 08:07:31.960663 | controller | pod "redhat-marketplace-j2js4" deleted 2025-09-30 08:07:32.302841 | controller | pod "redhat-marketplace-ps6xk" deleted 2025-09-30 08:07:32.339081 | controller | pod "redhat-operators-tqxl9" deleted 2025-09-30 08:07:32.418884 | controller | pod "redhat-operators-wzntl" deleted 2025-09-30 08:08:36.471822 | controller | ok 2025-09-30 08:08:36.477173 | 2025-09-30 08:08:36.477239 | TASK [Copy script ensure_services_up.sh] 2025-09-30 08:08:36.542435 | controller | skipping: Conditional result was False 2025-09-30 08:08:36.555235 | 2025-09-30 08:08:36.555380 | TASK [Ensure all pods are up and running] 2025-09-30 08:08:37.105956 | controller | skipping: Conditional result was False 2025-09-30 08:08:37.113850 | 2025-09-30 08:08:37.113935 | TASK [Check if there is a image build date file] 2025-09-30 08:08:37.772475 | controller | ok 2025-09-30 08:08:37.784392 | 2025-09-30 08:08:37.784541 | TASK [Print image date if available] 2025-09-30 08:08:38.207568 | controller | Tue Apr 1 06:17:46 PM EDT 2025 2025-09-30 08:08:38.333558 | controller | changed 2025-09-30 08:08:38.345393 | 2025-09-30 08:08:38.345522 | TASK [Fix machineconfigpool] 2025-09-30 08:08:38.423571 | controller | skipping: Conditional result was False 2025-09-30 08:08:38.435759 | 2025-09-30 08:08:38.435891 | TASK [Show available nodes] 2025-09-30 08:08:40.755620 | controller | NAME STATUS ROLES AGE VERSION 2025-09-30 08:08:40.758855 | controller | crc Ready control-plane,master,worker 219d v1.31.5 2025-09-30 08:08:40.993428 | controller | ok: Runtime: 0:00:01.892984 2025-09-30 08:08:41.012653 | 2025-09-30 08:08:41.012983 | TASK [Configure insecure registry inside crc vm] 2025-09-30 08:08:41.053645 | controller | skipping: Conditional result was False 2025-09-30 08:08:41.065837 | 2025-09-30 08:08:41.066002 | TASK [Catch CRC IP] 2025-09-30 08:08:41.643922 | controller | 192.168.130.11 2025-09-30 08:08:42.117025 | controller | changed 2025-09-30 08:08:42.129769 | 2025-09-30 08:08:42.129915 | TASK [Check if id_ed25519 key exists] 2025-09-30 08:08:42.567401 | controller | ok 2025-09-30 08:08:42.573191 | 2025-09-30 08:08:42.573253 | TASK [Set fact if new keypair exists] 2025-09-30 08:08:42.614101 | controller | ok 2025-09-30 08:08:42.619540 | 2025-09-30 08:08:42.619606 | TASK [Run crc] 2025-09-30 08:08:45.028759 | controller | 2025-09-30 08:08:54.093744 | controller | PLAY [OpenShift secret copy and CRC securitization] **************************** 2025-09-30 08:08:54.093805 | controller | 2025-09-30 08:08:54.093813 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:08:54.093826 | controller | [WARNING]: Platform linux on host 192.168.130.11 is using the discovered Python 2025-09-30 08:08:54.144290 | controller | interpreter at /usr/bin/python3.9, but future installation of another Python 2025-09-30 08:08:54.144336 | controller | interpreter could change the meaning of that path. See 2025-09-30 08:08:54.144343 | controller | https://docs.ansible.com/ansible- 2025-09-30 08:08:54.144350 | controller | core/2.14/reference_appendices/interpreter_discovery.html for more information. 2025-09-30 08:08:54.144363 | controller | ok: [192.168.130.11] 2025-09-30 08:08:56.035453 | controller | 2025-09-30 08:08:56.035543 | controller | TASK [Copy pull-secret] ******************************************************** 2025-09-30 08:08:56.035563 | controller | changed: [192.168.130.11] 2025-09-30 08:08:57.445641 | controller | 2025-09-30 08:08:57.445718 | controller | TASK [Add crio config] ********************************************************* 2025-09-30 08:08:57.445746 | controller | changed: [192.168.130.11] 2025-09-30 08:09:02.151160 | controller | 2025-09-30 08:09:02.151261 | controller | TASK [Restart crio to pickup new configuration] ******************************** 2025-09-30 08:09:02.151298 | controller | changed: [192.168.130.11] 2025-09-30 08:09:02.229418 | controller | 2025-09-30 08:09:02.229490 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:09:02.229499 | controller | 192.168.130.11 : ok=4 changed=3 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:09:02.229505 | controller | 2025-09-30 08:09:02.271052 | controller | changed 2025-09-30 08:09:02.283400 | 2025-09-30 08:09:02.283555 | TASK [Set slower etcd profile] 2025-09-30 08:09:02.363532 | controller | ok 2025-09-30 08:09:02.402252 | 2025-09-30 08:09:02.402401 | TASK [prepare-crc-cloud : Set slower profile] 2025-09-30 08:09:02.924592 | controller | etcd.operator.openshift.io/cluster patched 2025-09-30 08:09:02.962674 | controller | ok 2025-09-30 08:09:02.975782 | 2025-09-30 08:09:02.975975 | TASK [prepare-crc-cloud : Wait 30 seconds to apply] 2025-09-30 08:09:33.028587 | controller | ok 2025-09-30 08:09:33.041160 | 2025-09-30 08:09:33.041299 | TASK [prepare-crc-cloud : Get pod phase status] 2025-09-30 08:14:56.189012 | controller | ok 2025-09-30 08:14:56.211651 | 2025-09-30 08:14:56.211816 | TASK [Set limit for disk usage - IOPS and Read/Write] 2025-09-30 08:14:56.294773 | controller | ok 2025-09-30 08:14:56.314424 | controller | included: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/trusted/project_0/review.rdoproject.org/config/playbooks/crc/limit-disk-usage.yaml 2025-09-30 08:14:56.329544 | 2025-09-30 08:14:56.329653 | TASK [Set facts for disk limitation] 2025-09-30 08:14:56.364526 | controller | ok 2025-09-30 08:14:56.372937 | 2025-09-30 08:14:56.373042 | TASK [Print limits for the disk] 2025-09-30 08:14:56.419963 | controller | ok: Set limit to crc VM to the vda disk: iops 18000 read/write 262144000 2025-09-30 08:14:56.429100 | 2025-09-30 08:14:56.429332 | TASK [Set limit to crc VM to the vda disk] 2025-09-30 08:14:56.897099 | controller | 2025-09-30 08:14:57.005564 | controller | changed 2025-09-30 08:14:57.017962 | 2025-09-30 08:14:57.018114 | TASK [Pause machineconfigpool] 2025-09-30 08:14:57.099043 | controller | ok 2025-09-30 08:14:57.145316 | 2025-09-30 08:14:57.145627 | LOOP [prepare-crc-cloud : Pause the machineconfig configuration if mcp is not needed] 2025-09-30 08:14:57.750500 | controller | ok 2025-09-30 08:14:58.203803 | controller | ok 2025-09-30 08:14:58.218979 | 2025-09-30 08:14:58.219172 | TASK [prepare-crc-cloud : Print current machineconfigpool] 2025-09-30 08:14:58.786264 | controller | NAME CONFIG UPDATED UPDATING DEGRADED MACHINECOUNT READYMACHINECOUNT UPDATEDMACHINECOUNT DEGRADEDMACHINECOUNT AGE 2025-09-30 08:14:58.786363 | controller | master rendered-master-95020e6e79c40b4dd095817bccfc5060 True False False 1 1 1 0 219d 2025-09-30 08:14:58.786406 | controller | worker rendered-worker-594cc07c9feefb5e37f2530ac457d36c True False False 0 0 0 0 219d 2025-09-30 08:14:59.277981 | controller | ok 2025-09-30 08:14:59.331564 | 2025-09-30 08:14:59.331674 | PLAY [Set IOPS and Read/Write disk limitation excluding controller] 2025-09-30 08:14:59.331831 | 2025-09-30 08:14:59.331868 | PLAY RECAP 2025-09-30 08:14:59.331917 | controller | ok: 25 changed: 10 unreachable: 0 failed: 0 skipped: 12 rescued: 0 ignored: 0 2025-09-30 08:14:59.331944 | 2025-09-30 08:14:59.452498 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/crc/simple-start.yaml@master] 2025-09-30 08:14:59.455086 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main] 2025-09-30 08:15:00.123903 | 2025-09-30 08:15:00.124058 | PLAY [Run ci/playbooks/dump_zuul_data.yml] 2025-09-30 08:15:00.147510 | 2025-09-30 08:15:00.147609 | TASK [Create zuul-output directory] 2025-09-30 08:15:00.926320 | controller | changed 2025-09-30 08:15:00.937974 | 2025-09-30 08:15:00.938135 | TASK [Slurp Zuul inventory test] 2025-09-30 08:15:01.365246 | controller -> localhost | ok 2025-09-30 08:15:01.372716 | 2025-09-30 08:15:01.372785 | TASK [Save zuul inventory] 2025-09-30 08:15:02.898493 | controller | changed 2025-09-30 08:15:02.909820 | 2025-09-30 08:15:02.909981 | TASK [Save zuul vars without the change_message] 2025-09-30 08:15:04.335603 | controller | changed 2025-09-30 08:15:04.378029 | 2025-09-30 08:15:04.378167 | PLAY RECAP 2025-09-30 08:15:04.378227 | controller | ok: 4 changed: 3 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 08:15:04.378257 | 2025-09-30 08:15:04.492669 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/dump_zuul_data.yml@main] 2025-09-30 08:15:04.493535 | PRE-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main] 2025-09-30 08:15:05.151327 | 2025-09-30 08:15:05.151440 | PLAY [Run ci/playbooks/molecule-prepare.yml] 2025-09-30 08:15:05.174941 | 2025-09-30 08:15:05.175090 | TASK [Execute mirror info role to configure /etc/ci/mirror_info.sh] 2025-09-30 08:15:05.195537 | controller | ok 2025-09-30 08:15:05.214052 | 2025-09-30 08:15:05.214171 | TASK [mirror-info-fork : Set mirror_fqdn if not defined] 2025-09-30 08:15:05.239189 | controller | skipping: Conditional result was False 2025-09-30 08:15:05.245257 | 2025-09-30 08:15:05.245329 | TASK [mirror-info-fork : Create /etc/ci] 2025-09-30 08:15:05.764807 | controller | ok 2025-09-30 08:15:05.770649 | 2025-09-30 08:15:05.770751 | TASK [mirror-info-fork : Install ci_mirror script] 2025-09-30 08:15:07.034915 | controller | ok 2025-09-30 08:15:07.056987 | 2025-09-30 08:15:07.057121 | TASK [Prepare workspace] 2025-09-30 08:15:07.093781 | controller | ok 2025-09-30 08:15:07.126811 | 2025-09-30 08:15:07.126938 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-30 08:15:07.583805 | controller | ok 2025-09-30 08:15:07.597073 | 2025-09-30 08:15:07.597227 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-30 08:15:08.716031 | controller | Output suppressed because no_log was given 2025-09-30 08:15:08.737039 | 2025-09-30 08:15:08.737134 | LOOP [Create zuul-output directory] 2025-09-30 08:15:09.112147 | controller | changed: "/home/zuul/ci-framework-data/logs" 2025-09-30 08:15:09.356381 | controller | ok: "/home/zuul/zuul-output/logs" 2025-09-30 08:15:09.376367 | 2025-09-30 08:15:09.376506 | TASK [Install required packages] 2025-09-30 08:15:23.612098 | controller | ok: Nothing to do 2025-09-30 08:15:23.623184 | 2025-09-30 08:15:23.623308 | TASK [Install venv] 2025-09-30 08:16:25.944163 | controller | changed 2025-09-30 08:16:25.998907 | 2025-09-30 08:16:25.999009 | PLAY RECAP 2025-09-30 08:16:25.999071 | controller | ok: 7 changed: 2 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-30 08:16:25.999100 | 2025-09-30 08:16:26.112074 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-prepare.yml@main] 2025-09-30 08:16:26.112938 | RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main] 2025-09-30 08:16:26.753101 | 2025-09-30 08:16:26.753259 | PLAY [Run ci/playbooks/molecule-test.yml] 2025-09-30 08:16:26.775973 | 2025-09-30 08:16:26.776131 | TASK [Gather required facts] 2025-09-30 08:16:27.479361 | controller | ok 2025-09-30 08:16:27.491808 | 2025-09-30 08:16:27.492003 | TASK [Load environment var if instructed to] 2025-09-30 08:16:27.529727 | controller | skipping: Conditional result was False 2025-09-30 08:16:27.542948 | 2025-09-30 08:16:27.543133 | TASK [Run molecule] 2025-09-30 08:16:28.822265 | controller | INFO Found config file /home/zuul/src/github.com/openstack-k8s-operators/ci-framework/.config/molecule/config.yml 2025-09-30 08:16:29.065623 | controller | INFO Running default > destroy 2025-09-30 08:16:29.065983 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:16:29.076115 | controller | INFO Running default > create 2025-09-30 08:16:29.077082 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:16:29.085641 | controller | INFO Running default > converge 2025-09-30 08:16:29.925912 | controller | 2025-09-30 08:16:29.925990 | controller | PLAY [Converge] **************************************************************** 2025-09-30 08:16:29.926009 | controller | 2025-09-30 08:16:29.926023 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:16:29.926040 | controller | Tuesday 30 September 2025 08:16:29 +0000 (0:00:00.012) 0:00:00.012 ***** 2025-09-30 08:16:31.043567 | controller | ok: [instance] 2025-09-30 08:16:31.043640 | controller | 2025-09-30 08:16:31.043708 | controller | TASK [Add crc hostname with it's IP to /etc/hosts] ***************************** 2025-09-30 08:16:31.043851 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:01.120) 0:00:01.133 ***** 2025-09-30 08:16:31.424104 | controller | changed: [instance] 2025-09-30 08:16:31.424165 | controller | 2025-09-30 08:16:31.424298 | controller | TASK [Check if new ssh keypair exists] ***************************************** 2025-09-30 08:16:31.424440 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.380) 0:00:01.514 ***** 2025-09-30 08:16:31.456137 | controller | 2025-09-30 08:16:31.456229 | controller | TASK [recognize_ssh_keypair : Check if id_ed25519 key exists] ****************** 2025-09-30 08:16:31.456357 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.031) 0:00:01.546 ***** 2025-09-30 08:16:31.842529 | controller | ok: [instance] 2025-09-30 08:16:31.842785 | controller | 2025-09-30 08:16:31.867820 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair exists] ****************** 2025-09-30 08:16:31.867882 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.386) 0:00:01.932 ***** 2025-09-30 08:16:31.867897 | controller | ok: [instance] 2025-09-30 08:16:31.867973 | controller | 2025-09-30 08:16:31.867984 | controller | TASK [recognize_ssh_keypair : Set fact if new keypair does not exists] ********* 2025-09-30 08:16:31.868108 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.025) 0:00:01.957 ***** 2025-09-30 08:16:31.894107 | controller | skipping: [instance] 2025-09-30 08:16:31.894164 | controller | 2025-09-30 08:16:31.894310 | controller | TASK [Add the crc host dynamically] ******************************************** 2025-09-30 08:16:31.894417 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.026) 0:00:01.984 ***** 2025-09-30 08:16:31.917874 | controller | changed: [instance] 2025-09-30 08:16:31.917938 | controller | 2025-09-30 08:16:31.918071 | controller | TASK [Fetch crc network facts] ************************************************* 2025-09-30 08:16:31.918194 | controller | Tuesday 30 September 2025 08:16:31 +0000 (0:00:00.023) 0:00:02.008 ***** 2025-09-30 08:16:36.345063 | controller | ok: [instance -> crc] 2025-09-30 08:16:36.345188 | controller | 2025-09-30 08:16:36.345366 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:16:36.345575 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:04.426) 0:00:06.434 ***** 2025-09-30 08:16:36.372464 | controller | ok: [instance] 2025-09-30 08:16:36.372721 | controller | 2025-09-30 08:16:36.373282 | controller | TASK [Call ci_multus role] ***************************************************** 2025-09-30 08:16:36.373678 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.027) 0:00:06.461 ***** 2025-09-30 08:16:36.426365 | controller | 2025-09-30 08:16:36.426476 | controller | TASK [ci_multus : Create manifests directory] ********************************** 2025-09-30 08:16:36.426639 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.054) 0:00:06.515 ***** 2025-09-30 08:16:36.805076 | controller | changed: [instance] 2025-09-30 08:16:36.805152 | controller | 2025-09-30 08:16:36.805316 | controller | TASK [networking_mapper : Check for Networking Environment Definition file existence] *** 2025-09-30 08:16:36.805468 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.378) 0:00:06.894 ***** 2025-09-30 08:16:36.839468 | controller | skipping: [instance] 2025-09-30 08:16:36.839537 | controller | 2025-09-30 08:16:36.839692 | controller | TASK [networking_mapper : Check for Networking Definition file existance] ****** 2025-09-30 08:16:36.839824 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.034) 0:00:06.928 ***** 2025-09-30 08:16:36.873468 | controller | skipping: [instance] 2025-09-30 08:16:36.873750 | controller | 2025-09-30 08:16:36.874023 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************ 2025-09-30 08:16:36.874280 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.033) 0:00:06.962 ***** 2025-09-30 08:16:36.901929 | controller | skipping: [instance] 2025-09-30 08:16:36.902110 | controller | 2025-09-30 08:16:36.902682 | controller | TASK [networking_mapper : Set cifmw_networking_env_definition is present] ****** 2025-09-30 08:16:36.903016 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.028) 0:00:06.991 ***** 2025-09-30 08:16:36.940352 | controller | skipping: [instance] 2025-09-30 08:16:36.940559 | controller | 2025-09-30 08:16:36.940813 | controller | TASK [ci_multus : Gather network layout from OCP host or default networks] ***** 2025-09-30 08:16:36.941067 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.038) 0:00:07.029 ***** 2025-09-30 08:16:36.985740 | controller | ok: [instance] 2025-09-30 08:16:36.985927 | controller | 2025-09-30 08:16:36.986171 | controller | TASK [ci_multus : Merge any available multus net info patches] ***************** 2025-09-30 08:16:36.986427 | controller | Tuesday 30 September 2025 08:16:36 +0000 (0:00:00.045) 0:00:07.075 ***** 2025-09-30 08:16:37.177158 | controller | ok: [instance] => (item={'default': {'interface_name': 'eth0', 'network_name': 'default', 'gw_v4': '192.168.122.1', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'deny_network': {'gw_v4': '192.168.122.1', 'network_name': 'deny_network', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'not_allowed_network': {'gw_v4': '192.168.122.1', 'network_name': 'not_allowed_network', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'no_multus_network': {'gw_v4': '192.168.122.1', 'network_name': 'patchnetwork', 'network_v4': '192.168.122.0/24', 'interface_name': 'eth2'}}) 2025-09-30 08:16:37.177347 | controller | ok: [instance] => (item={'patchnetwork': {'gw_v4': '192.168.122.1', 'network_name': 'patchnetwork', 'network_v4': '192.168.122.0/24', 'interface_name': 'eth2', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'macvlan'}}}}) 2025-09-30 08:16:37.177377 | controller | ok: [instance] => (item={'bridge-to-linux-bridge': {'gw_v4': '192.168.122.1', 'network_name': 'bridge-to-linux-bridge', 'network_v4': '192.168.122.0/24', 'interface_name': 'eth1', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge', 'multus_attach': 'linux-bridge'}}}}) 2025-09-30 08:16:37.177747 | controller | 2025-09-30 08:16:37.271742 | controller | TASK [ci_multus : Remove any networks without Multus networking defined] ******* 2025-09-30 08:16:37.271878 | controller | Tuesday 30 September 2025 08:16:37 +0000 (0:00:00.191) 0:00:07.266 ***** 2025-09-30 08:16:37.271896 | controller | ok: [instance] 2025-09-30 08:16:37.271992 | controller | 2025-09-30 08:16:37.272002 | controller | TASK [ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined] *** 2025-09-30 08:16:37.272181 | controller | Tuesday 30 September 2025 08:16:37 +0000 (0:00:00.095) 0:00:07.361 ***** 2025-09-30 08:16:37.348491 | controller | ok: [instance] 2025-09-30 08:16:37.348579 | controller | 2025-09-30 08:16:37.348716 | controller | TASK [ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined] *** 2025-09-30 08:16:37.348824 | controller | Tuesday 30 September 2025 08:16:37 +0000 (0:00:00.076) 0:00:07.438 ***** 2025-09-30 08:16:37.441194 | controller | ok: [instance] 2025-09-30 08:16:37.441284 | controller | 2025-09-30 08:16:37.441404 | controller | TASK [ci_multus : Render NetworkAttachmenktDefinition manifests] *************** 2025-09-30 08:16:37.441543 | controller | Tuesday 30 September 2025 08:16:37 +0000 (0:00:00.092) 0:00:07.531 ***** 2025-09-30 08:16:38.047899 | controller | changed: [instance] 2025-09-30 08:16:38.048147 | controller | 2025-09-30 08:16:38.048272 | controller | TASK [ci_multus : Create the multus namespace] ********************************* 2025-09-30 08:16:38.048518 | controller | Tuesday 30 September 2025 08:16:38 +0000 (0:00:00.606) 0:00:08.137 ***** 2025-09-30 08:16:39.181809 | controller | changed: [instance] 2025-09-30 08:16:39.181888 | controller | 2025-09-30 08:16:39.181984 | controller | TASK [ci_multus : Apply network attachment definition manifests] *************** 2025-09-30 08:16:39.182089 | controller | Tuesday 30 September 2025 08:16:39 +0000 (0:00:01.134) 0:00:09.271 ***** 2025-09-30 08:16:40.017576 | controller | changed: [instance] 2025-09-30 08:16:40.017681 | controller | 2025-09-30 08:16:40.017813 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:16:40.017837 | controller | instance : ok=16 changed=6 unreachable=0 failed=0 skipped=5 rescued=0 ignored=0 2025-09-30 08:16:40.017926 | controller | 2025-09-30 08:16:40.018065 | controller | Tuesday 30 September 2025 08:16:40 +0000 (0:00:00.835) 0:00:10.107 ***** 2025-09-30 08:16:40.018196 | controller | =============================================================================== 2025-09-30 08:16:40.018318 | controller | Fetch crc network facts ------------------------------------------------- 4.43s 2025-09-30 08:16:40.018501 | controller | ci_multus : Create the multus namespace --------------------------------- 1.13s 2025-09-30 08:16:40.018616 | controller | Gathering Facts --------------------------------------------------------- 1.12s 2025-09-30 08:16:40.018780 | controller | ci_multus : Apply network attachment definition manifests --------------- 0.84s 2025-09-30 08:16:40.018884 | controller | ci_multus : Render NetworkAttachmenktDefinition manifests --------------- 0.61s 2025-09-30 08:16:40.018970 | controller | recognize_ssh_keypair : Check if id_ed25519 key exists ------------------ 0.39s 2025-09-30 08:16:40.019063 | controller | Add crc hostname with it's IP to /etc/hosts ----------------------------- 0.38s 2025-09-30 08:16:40.019163 | controller | ci_multus : Create manifests directory ---------------------------------- 0.38s 2025-09-30 08:16:40.019274 | controller | ci_multus : Merge any available multus net info patches ----------------- 0.19s 2025-09-30 08:16:40.019435 | controller | ci_multus : Remove any networks without Multus networking defined ------- 0.10s 2025-09-30 08:16:40.019586 | controller | ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined --- 0.09s 2025-09-30 08:16:40.019707 | controller | ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined --- 0.08s 2025-09-30 08:16:40.019816 | controller | Call ci_multus role ----------------------------------------------------- 0.05s 2025-09-30 08:16:40.019949 | controller | ci_multus : Gather network layout from OCP host or default networks ----- 0.05s 2025-09-30 08:16:40.020052 | controller | networking_mapper : Set cifmw_networking_env_definition is present ------ 0.04s 2025-09-30 08:16:40.020152 | controller | networking_mapper : Check for Networking Environment Definition file existence --- 0.03s 2025-09-30 08:16:40.020246 | controller | networking_mapper : Check for Networking Definition file existance ------ 0.03s 2025-09-30 08:16:40.020359 | controller | Check if new ssh keypair exists ----------------------------------------- 0.03s 2025-09-30 08:16:40.020537 | controller | networking_mapper : Load the Networking Definition from file ------------ 0.03s 2025-09-30 08:16:40.020669 | controller | Load shared variables --------------------------------------------------- 0.03s 2025-09-30 08:16:40.097160 | controller | INFO Running default > verify 2025-09-30 08:16:40.097397 | controller | INFO Running Ansible Verifier 2025-09-30 08:16:40.653543 | controller | 2025-09-30 08:16:40.655630 | controller | PLAY [Verify] ****************************************************************** 2025-09-30 08:16:41.765121 | controller | 2025-09-30 08:16:41.765171 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:16:41.765197 | controller | Tuesday 30 September 2025 08:16:40 +0000 (0:00:00.018) 0:00:00.018 ***** 2025-09-30 08:16:41.765210 | controller | ok: [instance] 2025-09-30 08:16:41.765242 | controller | 2025-09-30 08:16:41.765465 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:16:41.765599 | controller | Tuesday 30 September 2025 08:16:41 +0000 (0:00:01.111) 0:00:01.129 ***** 2025-09-30 08:16:41.789900 | controller | ok: [instance] 2025-09-30 08:16:41.790196 | controller | 2025-09-30 08:16:41.790209 | controller | TASK [Fetch files stat results] ************************************************ 2025-09-30 08:16:41.790719 | controller | Tuesday 30 September 2025 08:16:41 +0000 (0:00:00.024) 0:00:01.154 ***** 2025-09-30 08:16:42.193074 | controller | ok: [instance] 2025-09-30 08:16:42.193160 | controller | 2025-09-30 08:16:42.193199 | controller | TASK [Assert that expected file exist] ***************************************** 2025-09-30 08:16:42.193309 | controller | Tuesday 30 September 2025 08:16:42 +0000 (0:00:00.402) 0:00:01.556 ***** 2025-09-30 08:16:42.221343 | controller | ok: [instance] => changed=false 2025-09-30 08:16:42.221437 | controller | msg: All assertions passed 2025-09-30 08:16:42.221448 | controller | 2025-09-30 08:16:42.221585 | controller | TASK [Fetch file content] ****************************************************** 2025-09-30 08:16:42.221689 | controller | Tuesday 30 September 2025 08:16:42 +0000 (0:00:00.028) 0:00:01.585 ***** 2025-09-30 08:16:42.594622 | controller | ok: [instance] 2025-09-30 08:16:42.594784 | controller | 2025-09-30 08:16:42.595039 | controller | TASK [Set _ci_multus_nad variable] ********************************************* 2025-09-30 08:16:42.595461 | controller | Tuesday 30 September 2025 08:16:42 +0000 (0:00:00.372) 0:00:01.958 ***** 2025-09-30 08:16:42.645913 | controller | ok: [instance] 2025-09-30 08:16:42.646169 | controller | 2025-09-30 08:16:42.646181 | controller | TASK [Assert expected number of Network Attachment Definitions are created] **** 2025-09-30 08:16:42.646194 | controller | Tuesday 30 September 2025 08:16:42 +0000 (0:00:00.051) 0:00:02.009 ***** 2025-09-30 08:16:42.723052 | controller | ok: [instance] 2025-09-30 08:16:42.723206 | controller | 2025-09-30 08:16:42.723388 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:16:42.723619 | controller | instance : ok=7 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:16:42.723782 | controller | 2025-09-30 08:16:42.724005 | controller | Tuesday 30 September 2025 08:16:42 +0000 (0:00:00.078) 0:00:02.088 ***** 2025-09-30 08:16:42.724214 | controller | =============================================================================== 2025-09-30 08:16:42.724548 | controller | Gathering Facts --------------------------------------------------------- 1.11s 2025-09-30 08:16:42.724677 | controller | Fetch files stat results ------------------------------------------------ 0.40s 2025-09-30 08:16:42.724894 | controller | Fetch file content ------------------------------------------------------ 0.37s 2025-09-30 08:16:42.725118 | controller | Assert expected number of Network Attachment Definitions are created ---- 0.08s 2025-09-30 08:16:42.725301 | controller | Set _ci_multus_nad variable --------------------------------------------- 0.05s 2025-09-30 08:16:42.725556 | controller | Assert that expected file exist ----------------------------------------- 0.03s 2025-09-30 08:16:42.725762 | controller | Load shared variables --------------------------------------------------- 0.02s 2025-09-30 08:16:42.791153 | controller | INFO Verifier completed successfully. 2025-09-30 08:16:42.810235 | controller | INFO Running default > verify 2025-09-30 08:16:42.810636 | controller | INFO Running Ansible Verifier 2025-09-30 08:16:43.281225 | controller | 2025-09-30 08:16:43.281701 | controller | PLAY [Verify CRC] ************************************************************** 2025-09-30 08:16:43.281927 | controller | 2025-09-30 08:16:43.281991 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:16:43.282569 | controller | Tuesday 30 September 2025 08:16:43 +0000 (0:00:00.015) 0:00:00.015 ***** 2025-09-30 08:16:44.369509 | controller | ok: [instance] 2025-09-30 08:16:44.370171 | controller | 2025-09-30 08:16:44.409663 | controller | TASK [Include default vars] **************************************************** 2025-09-30 08:16:44.409719 | controller | Tuesday 30 September 2025 08:16:44 +0000 (0:00:01.088) 0:00:01.104 ***** 2025-09-30 08:16:44.409737 | controller | ok: [instance] 2025-09-30 08:16:44.409770 | controller | 2025-09-30 08:16:44.409945 | controller | TASK [Check if NADs were created] ********************************************** 2025-09-30 08:16:44.410117 | controller | Tuesday 30 September 2025 08:16:44 +0000 (0:00:00.040) 0:00:01.144 ***** 2025-09-30 08:16:45.258082 | controller | ok: [instance] 2025-09-30 08:16:45.258157 | controller | 2025-09-30 08:16:45.258179 | controller | TASK [Store output spec] ******************************************************* 2025-09-30 08:16:45.258291 | controller | Tuesday 30 September 2025 08:16:45 +0000 (0:00:00.848) 0:00:01.993 ***** 2025-09-30 08:16:45.317759 | controller | ok: [instance] 2025-09-30 08:16:45.317939 | controller | 2025-09-30 08:16:45.318096 | controller | TASK [Ensure both lists have the same length] ********************************** 2025-09-30 08:16:45.318234 | controller | Tuesday 30 September 2025 08:16:45 +0000 (0:00:00.059) 0:00:02.052 ***** 2025-09-30 08:16:45.367730 | controller | ok: [instance] => changed=false 2025-09-30 08:16:45.367833 | controller | msg: All assertions passed 2025-09-30 08:16:45.368034 | controller | 2025-09-30 08:16:45.368173 | controller | TASK [Compare each corresponding element in the lists] ************************* 2025-09-30 08:16:45.368330 | controller | Tuesday 30 September 2025 08:16:45 +0000 (0:00:00.049) 0:00:02.102 ***** 2025-09-30 08:16:45.438722 | controller | ok: [instance] => (item=['{\n "cniVersion": "0.3.1",\n "name": "bridge-to-linux-bridge",\n "type": "bridge",\n "bridge": "bridge-to-linux-bridge",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}', '{\n "cniVersion": "0.3.1",\n "name": "bridge-to-linux-bridge",\n "type": "bridge",\n "bridge": "bridge-to-linux-bridge",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}\n']) => changed=false 2025-09-30 08:16:45.438891 | controller | ansible_loop_var: item 2025-09-30 08:16:45.439108 | controller | item: 2025-09-30 08:16:45.439295 | controller | - |- 2025-09-30 08:16:45.439537 | controller | { 2025-09-30 08:16:45.439728 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.440040 | controller | "name": "bridge-to-linux-bridge", 2025-09-30 08:16:45.440332 | controller | "type": "bridge", 2025-09-30 08:16:45.440360 | controller | "bridge": "bridge-to-linux-bridge", 2025-09-30 08:16:45.440656 | controller | "ipam": { 2025-09-30 08:16:45.440916 | controller | "type": "whereabouts", 2025-09-30 08:16:45.441038 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.441229 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.441432 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.441782 | controller | } 2025-09-30 08:16:45.441839 | controller | } 2025-09-30 08:16:45.442214 | controller | - |- 2025-09-30 08:16:45.442255 | controller | { 2025-09-30 08:16:45.442451 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.442651 | controller | "name": "bridge-to-linux-bridge", 2025-09-30 08:16:45.443221 | controller | "type": "bridge", 2025-09-30 08:16:45.443412 | controller | "bridge": "bridge-to-linux-bridge", 2025-09-30 08:16:45.443440 | controller | "ipam": { 2025-09-30 08:16:45.443460 | controller | "type": "whereabouts", 2025-09-30 08:16:45.443623 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.443801 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.444051 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.444233 | controller | } 2025-09-30 08:16:45.444415 | controller | } 2025-09-30 08:16:45.444604 | controller | msg: All assertions passed 2025-09-30 08:16:45.444888 | controller | ok: [instance] => (item=['{\n "cniVersion": "0.3.1",\n "name": "default",\n "type": "bridge",\n "bridge": "eth0",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}\n', '{\n "cniVersion": "0.3.1",\n "name": "default",\n "type": "bridge",\n "bridge": "eth0",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}\n']) => changed=false 2025-09-30 08:16:45.445075 | controller | ansible_loop_var: item 2025-09-30 08:16:45.445227 | controller | item: 2025-09-30 08:16:45.445419 | controller | - |- 2025-09-30 08:16:45.445608 | controller | { 2025-09-30 08:16:45.445808 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.445994 | controller | "name": "default", 2025-09-30 08:16:45.446182 | controller | "type": "bridge", 2025-09-30 08:16:45.446368 | controller | "bridge": "eth0", 2025-09-30 08:16:45.446592 | controller | "ipam": { 2025-09-30 08:16:45.446792 | controller | "type": "whereabouts", 2025-09-30 08:16:45.447026 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.447183 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.447302 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.447444 | controller | } 2025-09-30 08:16:45.448350 | controller | } 2025-09-30 08:16:45.448592 | controller | - |- 2025-09-30 08:16:45.448758 | controller | { 2025-09-30 08:16:45.448999 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.449187 | controller | "name": "default", 2025-09-30 08:16:45.449415 | controller | "type": "bridge", 2025-09-30 08:16:45.449610 | controller | "bridge": "eth0", 2025-09-30 08:16:45.449812 | controller | "ipam": { 2025-09-30 08:16:45.449982 | controller | "type": "whereabouts", 2025-09-30 08:16:45.450194 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.450369 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.450588 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.450712 | controller | } 2025-09-30 08:16:45.450925 | controller | } 2025-09-30 08:16:45.451086 | controller | msg: All assertions passed 2025-09-30 08:16:45.451293 | controller | ok: [instance] => (item=['{\n "cniVersion": "0.3.1",\n "name": "patchnetwork",\n "type": "macvlan",\n "master": "eth2",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}\n', '{\n "cniVersion": "0.3.1",\n "name": "patchnetwork",\n "type": "macvlan",\n "master": "eth2",\n "ipam": {\n "type": "whereabouts",\n "range": "192.168.122.0/24",\n "range_start": "192.168.122.30",\n "range_end": "192.168.122.70"\n }\n}']) => changed=false 2025-09-30 08:16:45.451449 | controller | ansible_loop_var: item 2025-09-30 08:16:45.451588 | controller | item: 2025-09-30 08:16:45.451773 | controller | - |- 2025-09-30 08:16:45.451947 | controller | { 2025-09-30 08:16:45.452135 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.452266 | controller | "name": "patchnetwork", 2025-09-30 08:16:45.452416 | controller | "type": "macvlan", 2025-09-30 08:16:45.452563 | controller | "master": "eth2", 2025-09-30 08:16:45.452704 | controller | "ipam": { 2025-09-30 08:16:45.452880 | controller | "type": "whereabouts", 2025-09-30 08:16:45.453056 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.453265 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.453478 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.453658 | controller | } 2025-09-30 08:16:45.453873 | controller | } 2025-09-30 08:16:45.454074 | controller | - |- 2025-09-30 08:16:45.454236 | controller | { 2025-09-30 08:16:45.454450 | controller | "cniVersion": "0.3.1", 2025-09-30 08:16:45.454635 | controller | "name": "patchnetwork", 2025-09-30 08:16:45.454865 | controller | "type": "macvlan", 2025-09-30 08:16:45.454992 | controller | "master": "eth2", 2025-09-30 08:16:45.455164 | controller | "ipam": { 2025-09-30 08:16:45.455349 | controller | "type": "whereabouts", 2025-09-30 08:16:45.455634 | controller | "range": "192.168.122.0/24", 2025-09-30 08:16:45.455785 | controller | "range_start": "192.168.122.30", 2025-09-30 08:16:45.455964 | controller | "range_end": "192.168.122.70" 2025-09-30 08:16:45.456195 | controller | } 2025-09-30 08:16:45.456625 | controller | } 2025-09-30 08:16:45.456980 | controller | msg: All assertions passed 2025-09-30 08:16:45.457000 | controller | 2025-09-30 08:16:45.457165 | controller | TASK [Create a test pod to attach a network] *********************************** 2025-09-30 08:16:45.457184 | controller | Tuesday 30 September 2025 08:16:45 +0000 (0:00:00.070) 0:00:02.173 ***** 2025-09-30 08:17:37.855131 | controller | [WARNING]: unknown field "api_version" 2025-09-30 08:17:37.863254 | controller | FAILED - RETRYING: [instance]: Create a test pod to attach a network (30 retries left). 2025-09-30 08:17:37.863378 | controller | FAILED - RETRYING: [instance]: Create a test pod to attach a network (29 retries left). 2025-09-30 08:17:37.863504 | controller | changed: [instance] 2025-09-30 08:17:37.863644 | controller | 2025-09-30 08:17:37.863760 | controller | TASK [Assert that test pod has the additional network] ************************* 2025-09-30 08:17:37.863996 | controller | Tuesday 30 September 2025 08:17:37 +0000 (0:00:52.425) 0:00:54.598 ***** 2025-09-30 08:17:37.888897 | controller | ok: [instance] => changed=false 2025-09-30 08:17:37.889021 | controller | msg: All assertions passed 2025-09-30 08:17:37.889140 | controller | 2025-09-30 08:17:37.889338 | controller | TASK [Delete test pod] ********************************************************* 2025-09-30 08:17:37.889480 | controller | Tuesday 30 September 2025 08:17:37 +0000 (0:00:00.025) 0:00:54.624 ***** 2025-09-30 08:17:38.619095 | controller | changed: [instance] 2025-09-30 08:17:38.619154 | controller | 2025-09-30 08:17:38.619275 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:38.619405 | controller | instance : ok=9 changed=2 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:17:38.619507 | controller | 2025-09-30 08:17:38.619608 | controller | Tuesday 30 September 2025 08:17:38 +0000 (0:00:00.730) 0:00:55.354 ***** 2025-09-30 08:17:38.619704 | controller | =============================================================================== 2025-09-30 08:17:38.619806 | controller | Create a test pod to attach a network ---------------------------------- 52.43s 2025-09-30 08:17:38.619901 | controller | Gathering Facts --------------------------------------------------------- 1.09s 2025-09-30 08:17:38.620005 | controller | Check if NADs were created ---------------------------------------------- 0.85s 2025-09-30 08:17:38.620096 | controller | Delete test pod --------------------------------------------------------- 0.73s 2025-09-30 08:17:38.620191 | controller | Compare each corresponding element in the lists ------------------------- 0.07s 2025-09-30 08:17:38.620303 | controller | Store output spec ------------------------------------------------------- 0.06s 2025-09-30 08:17:38.620402 | controller | Ensure both lists have the same length ---------------------------------- 0.05s 2025-09-30 08:17:38.620511 | controller | Include default vars ---------------------------------------------------- 0.04s 2025-09-30 08:17:38.620613 | controller | Assert that test pod has the additional network ------------------------- 0.03s 2025-09-30 08:17:38.679466 | controller | INFO Verifier completed successfully. 2025-09-30 08:17:38.693340 | controller | INFO Running default > side_effect 2025-09-30 08:17:39.187015 | controller | 2025-09-30 08:17:39.187136 | controller | PLAY [Clean] ******************************************************************* 2025-09-30 08:17:39.187266 | controller | 2025-09-30 08:17:39.187416 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:39.187593 | controller | Tuesday 30 September 2025 08:17:39 +0000 (0:00:00.017) 0:00:00.017 ***** 2025-09-30 08:17:40.303908 | controller | ok: [instance] 2025-09-30 08:17:40.304021 | controller | 2025-09-30 08:17:40.304144 | controller | TASK [Backup NAD before cleanup so they can be inspected in CI] **************** 2025-09-30 08:17:40.304300 | controller | Tuesday 30 September 2025 08:17:40 +0000 (0:00:01.117) 0:00:01.134 ***** 2025-09-30 08:17:40.673019 | controller | changed: [instance] 2025-09-30 08:17:41.640977 | controller | 2025-09-30 08:17:41.641017 | controller | TASK [ci_multus : Cleanup - Fetch NADs in namespace: openstack] **************** 2025-09-30 08:17:41.641026 | controller | Tuesday 30 September 2025 08:17:40 +0000 (0:00:00.369) 0:00:01.503 ***** 2025-09-30 08:17:41.641037 | controller | ok: [instance] 2025-09-30 08:17:44.105461 | controller | 2025-09-30 08:17:44.105520 | controller | TASK [ci_multus : Cleanup - Delete NADs] *************************************** 2025-09-30 08:17:44.105529 | controller | Tuesday 30 September 2025 08:17:41 +0000 (0:00:00.967) 0:00:02.471 ***** 2025-09-30 08:17:44.105542 | controller | changed: [instance] => (item=bridge-to-linux-bridge) 2025-09-30 08:17:44.105727 | controller | changed: [instance] => (item=default) 2025-09-30 08:17:44.105743 | controller | changed: [instance] => (item=patchnetwork) 2025-09-30 08:17:44.105750 | controller | 2025-09-30 08:17:44.105756 | controller | TASK [ci_multus : Cleanup - Remove if artifact directory exists] *************** 2025-09-30 08:17:44.105765 | controller | Tuesday 30 September 2025 08:17:44 +0000 (0:00:02.464) 0:00:04.935 ***** 2025-09-30 08:17:44.485900 | controller | changed: [instance] 2025-09-30 08:17:44.485944 | controller | 2025-09-30 08:17:44.486057 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:44.486193 | controller | instance : ok=5 changed=3 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:17:44.486289 | controller | 2025-09-30 08:17:44.486424 | controller | Tuesday 30 September 2025 08:17:44 +0000 (0:00:00.381) 0:00:05.317 ***** 2025-09-30 08:17:44.486513 | controller | =============================================================================== 2025-09-30 08:17:44.486612 | controller | ci_multus : Cleanup - Delete NADs --------------------------------------- 2.46s 2025-09-30 08:17:44.486731 | controller | Gathering Facts --------------------------------------------------------- 1.12s 2025-09-30 08:17:44.486874 | controller | ci_multus : Cleanup - Fetch NADs in namespace: openstack ---------------- 0.97s 2025-09-30 08:17:44.486995 | controller | ci_multus : Cleanup - Remove if artifact directory exists --------------- 0.38s 2025-09-30 08:17:44.487112 | controller | Backup NAD before cleanup so they can be inspected in CI ---------------- 0.37s 2025-09-30 08:17:44.568780 | controller | INFO Running default > verify 2025-09-30 08:17:44.569156 | controller | INFO Running Ansible Verifier 2025-09-30 08:17:45.087253 | controller | 2025-09-30 08:17:45.087327 | controller | PLAY [Verify Clean] ************************************************************ 2025-09-30 08:17:45.087395 | controller | 2025-09-30 08:17:45.087521 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:45.087643 | controller | Tuesday 30 September 2025 08:17:45 +0000 (0:00:00.017) 0:00:00.017 ***** 2025-09-30 08:17:46.147048 | controller | ok: [instance] 2025-09-30 08:17:46.147150 | controller | 2025-09-30 08:17:46.147309 | controller | TASK [Include default vars] **************************************************** 2025-09-30 08:17:46.147502 | controller | Tuesday 30 September 2025 08:17:46 +0000 (0:00:01.059) 0:00:01.077 ***** 2025-09-30 08:17:46.174285 | controller | ok: [instance] 2025-09-30 08:17:46.174411 | controller | 2025-09-30 08:17:46.174606 | controller | TASK [Fetch file stat results] ************************************************* 2025-09-30 08:17:46.174750 | controller | Tuesday 30 September 2025 08:17:46 +0000 (0:00:00.027) 0:00:01.104 ***** 2025-09-30 08:17:46.548463 | controller | ok: [instance] 2025-09-30 08:17:46.548507 | controller | 2025-09-30 08:17:46.548648 | controller | TASK [Assert that created file are removed by cleanup] ************************* 2025-09-30 08:17:46.548760 | controller | Tuesday 30 September 2025 08:17:46 +0000 (0:00:00.374) 0:00:01.478 ***** 2025-09-30 08:17:46.596841 | controller | ok: [instance] => changed=false 2025-09-30 08:17:46.596883 | controller | msg: All assertions passed 2025-09-30 08:17:46.596999 | controller | 2025-09-30 08:17:46.597100 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:46.597223 | controller | instance : ok=4 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:17:46.597317 | controller | 2025-09-30 08:17:46.597432 | controller | Tuesday 30 September 2025 08:17:46 +0000 (0:00:00.049) 0:00:01.527 ***** 2025-09-30 08:17:46.597586 | controller | =============================================================================== 2025-09-30 08:17:46.597683 | controller | Gathering Facts --------------------------------------------------------- 1.06s 2025-09-30 08:17:46.597776 | controller | Fetch file stat results ------------------------------------------------- 0.37s 2025-09-30 08:17:46.597868 | controller | Assert that created file are removed by cleanup ------------------------- 0.05s 2025-09-30 08:17:46.597964 | controller | Include default vars ---------------------------------------------------- 0.03s 2025-09-30 08:17:46.667975 | controller | INFO Verifier completed successfully. 2025-09-30 08:17:46.688812 | controller | INFO Running default > verify 2025-09-30 08:17:46.689401 | controller | INFO Running Ansible Verifier 2025-09-30 08:17:47.215790 | controller | 2025-09-30 08:17:47.216222 | controller | PLAY [Verify Clean CRC] ******************************************************** 2025-09-30 08:17:48.267860 | controller | 2025-09-30 08:17:48.267904 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:48.267912 | controller | Tuesday 30 September 2025 08:17:47 +0000 (0:00:00.017) 0:00:00.017 ***** 2025-09-30 08:17:48.267923 | controller | ok: [instance] 2025-09-30 08:17:48.268053 | controller | 2025-09-30 08:17:48.268096 | controller | TASK [Include default vars] **************************************************** 2025-09-30 08:17:48.268117 | controller | Tuesday 30 September 2025 08:17:48 +0000 (0:00:01.051) 0:00:01.068 ***** 2025-09-30 08:17:48.306104 | controller | ok: [instance] 2025-09-30 08:17:48.306156 | controller | 2025-09-30 08:17:48.306164 | controller | TASK [Check if NADs were deleted] ********************************************** 2025-09-30 08:17:48.306172 | controller | Tuesday 30 September 2025 08:17:48 +0000 (0:00:00.038) 0:00:01.107 ***** 2025-09-30 08:17:49.284286 | controller | ok: [instance] 2025-09-30 08:17:49.284341 | controller | 2025-09-30 08:17:49.284513 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:49.284665 | controller | instance : ok=3 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:17:49.284821 | controller | 2025-09-30 08:17:49.284863 | controller | Tuesday 30 September 2025 08:17:49 +0000 (0:00:00.978) 0:00:02.086 ***** 2025-09-30 08:17:49.284968 | controller | =============================================================================== 2025-09-30 08:17:49.285067 | controller | Gathering Facts --------------------------------------------------------- 1.05s 2025-09-30 08:17:49.285222 | controller | Check if NADs were deleted ---------------------------------------------- 0.98s 2025-09-30 08:17:49.285416 | controller | Include default vars ---------------------------------------------------- 0.04s 2025-09-30 08:17:49.353104 | controller | INFO Verifier completed successfully. 2025-09-30 08:17:49.353957 | controller | INFO Pruning extra files from scenario ephemeral directory 2025-09-30 08:17:49.379451 | controller | INFO Running local > destroy 2025-09-30 08:17:49.380183 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:17:49.400254 | controller | INFO Running local > create 2025-09-30 08:17:49.402551 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:17:49.420126 | controller | INFO Running local > converge 2025-09-30 08:17:49.925109 | controller | 2025-09-30 08:17:49.925170 | controller | PLAY [Converge] **************************************************************** 2025-09-30 08:17:49.925234 | controller | 2025-09-30 08:17:49.925344 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:49.925473 | controller | Tuesday 30 September 2025 08:17:49 +0000 (0:00:00.020) 0:00:00.020 ***** 2025-09-30 08:17:51.003092 | controller | ok: [instance] 2025-09-30 08:17:51.003155 | controller | 2025-09-30 08:17:51.003332 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:17:51.003532 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:01.078) 0:00:01.098 ***** 2025-09-30 08:17:51.029456 | controller | ok: [instance] 2025-09-30 08:17:51.029622 | controller | 2025-09-30 08:17:51.029767 | controller | TASK [Call ci_multus role] ***************************************************** 2025-09-30 08:17:51.029907 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.026) 0:00:01.125 ***** 2025-09-30 08:17:51.074461 | controller | 2025-09-30 08:17:51.074615 | controller | TASK [ci_multus : Create manifests directory] ********************************** 2025-09-30 08:17:51.075002 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.044) 0:00:01.169 ***** 2025-09-30 08:17:51.492181 | controller | changed: [instance] 2025-09-30 08:17:51.492426 | controller | 2025-09-30 08:17:51.492759 | controller | TASK [networking_mapper : Check for Networking Environment Definition file existence] *** 2025-09-30 08:17:51.493001 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.417) 0:00:01.587 ***** 2025-09-30 08:17:51.534056 | controller | skipping: [instance] 2025-09-30 08:17:51.534122 | controller | 2025-09-30 08:17:51.534336 | controller | TASK [networking_mapper : Check for Networking Definition file existance] ****** 2025-09-30 08:17:51.534494 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.042) 0:00:01.629 ***** 2025-09-30 08:17:51.576261 | controller | skipping: [instance] 2025-09-30 08:17:51.576351 | controller | 2025-09-30 08:17:51.576597 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************ 2025-09-30 08:17:51.576800 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.041) 0:00:01.671 ***** 2025-09-30 08:17:51.610206 | controller | skipping: [instance] 2025-09-30 08:17:51.610293 | controller | 2025-09-30 08:17:51.610543 | controller | TASK [networking_mapper : Set cifmw_networking_env_definition is present] ****** 2025-09-30 08:17:51.610724 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.034) 0:00:01.705 ***** 2025-09-30 08:17:51.654459 | controller | skipping: [instance] 2025-09-30 08:17:51.654633 | controller | 2025-09-30 08:17:51.654876 | controller | TASK [ci_multus : Gather network layout from OCP host or default networks] ***** 2025-09-30 08:17:51.655115 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.044) 0:00:01.749 ***** 2025-09-30 08:17:51.693558 | controller | ok: [instance] 2025-09-30 08:17:51.693748 | controller | 2025-09-30 08:17:51.694172 | controller | TASK [ci_multus : Merge any available multus net info patches] ***************** 2025-09-30 08:17:51.694554 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.039) 0:00:01.788 ***** 2025-09-30 08:17:51.851127 | controller | ok: [instance] => (item={'default': {'interface_name': 'eth0', 'network_name': 'default', 'gw_v4': '192.168.122.1', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'deny_network': {'gw_v4': '192.168.122.1', 'network_name': 'deny_network', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'not_allowed_network': {'gw_v4': '192.168.122.1', 'network_name': 'not_allowed_network', 'network_v4': '192.168.122.0/24', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}], 'multus_type': 'bridge'}}}, 'no_multus_network': {'gw_v4': '192.168.122.1', 'network_name': 'patchnetwork', 'network_v4': '192.168.122.0/24', 'interface_name': 'eth2'}}) 2025-09-30 08:17:51.851405 | controller | ok: [instance] => (item={'patchnetwork': {'gw_v4': '192.168.122.1', 'network_name': 'patchnetwork', 'network_v4': '192.168.122.0/24', 'interface_name': 'eth2', 'tools': {'multus': {'ipv4_ranges': [{'start': '192.168.122.30', 'end': '192.168.122.70'}]}}}}) 2025-09-30 08:17:51.851911 | controller | 2025-09-30 08:17:51.852151 | controller | TASK [ci_multus : Remove any networks without Multus networking defined] ******* 2025-09-30 08:17:51.852415 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.156) 0:00:01.945 ***** 2025-09-30 08:17:51.974365 | controller | ok: [instance] 2025-09-30 08:17:51.974442 | controller | 2025-09-30 08:17:51.974513 | controller | TASK [ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined] *** 2025-09-30 08:17:51.974614 | controller | Tuesday 30 September 2025 08:17:51 +0000 (0:00:00.123) 0:00:02.069 ***** 2025-09-30 08:17:52.054870 | controller | ok: [instance] 2025-09-30 08:17:52.054921 | controller | 2025-09-30 08:17:52.055025 | controller | TASK [ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined] *** 2025-09-30 08:17:52.055121 | controller | Tuesday 30 September 2025 08:17:52 +0000 (0:00:00.080) 0:00:02.149 ***** 2025-09-30 08:17:52.157157 | controller | ok: [instance] 2025-09-30 08:17:52.157412 | controller | 2025-09-30 08:17:52.157754 | controller | TASK [ci_multus : Render NetworkAttachmenktDefinition manifests] *************** 2025-09-30 08:17:52.158056 | controller | Tuesday 30 September 2025 08:17:52 +0000 (0:00:00.101) 0:00:02.251 ***** 2025-09-30 08:17:52.883876 | controller | changed: [instance] 2025-09-30 08:17:52.883977 | controller | 2025-09-30 08:17:52.884126 | controller | TASK [ci_multus : Create the multus namespace] ********************************* 2025-09-30 08:17:52.884283 | controller | Tuesday 30 September 2025 08:17:52 +0000 (0:00:00.727) 0:00:02.979 ***** 2025-09-30 08:17:52.903821 | controller | skipping: [instance] 2025-09-30 08:17:52.903949 | controller | 2025-09-30 08:17:52.904163 | controller | TASK [ci_multus : Apply network attachment definition manifests] *************** 2025-09-30 08:17:52.904402 | controller | Tuesday 30 September 2025 08:17:52 +0000 (0:00:00.019) 0:00:02.999 ***** 2025-09-30 08:17:52.942352 | controller | skipping: [instance] 2025-09-30 08:17:52.942677 | controller | 2025-09-30 08:17:52.942888 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:52.943140 | controller | instance : ok=9 changed=2 unreachable=0 failed=0 skipped=6 rescued=0 ignored=0 2025-09-30 08:17:52.943348 | controller | 2025-09-30 08:17:52.943627 | controller | Tuesday 30 September 2025 08:17:52 +0000 (0:00:00.038) 0:00:03.037 ***** 2025-09-30 08:17:52.943871 | controller | =============================================================================== 2025-09-30 08:17:52.944114 | controller | Gathering Facts --------------------------------------------------------- 1.08s 2025-09-30 08:17:52.944312 | controller | ci_multus : Render NetworkAttachmenktDefinition manifests --------------- 0.73s 2025-09-30 08:17:52.944548 | controller | ci_multus : Create manifests directory ---------------------------------- 0.42s 2025-09-30 08:17:52.944762 | controller | ci_multus : Merge any available multus net info patches ----------------- 0.16s 2025-09-30 08:17:52.944951 | controller | ci_multus : Remove any networks without Multus networking defined ------- 0.12s 2025-09-30 08:17:52.945225 | controller | ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined --- 0.10s 2025-09-30 08:17:52.945501 | controller | ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined --- 0.08s 2025-09-30 08:17:52.945695 | controller | Call ci_multus role ----------------------------------------------------- 0.04s 2025-09-30 08:17:52.945982 | controller | networking_mapper : Set cifmw_networking_env_definition is present ------ 0.04s 2025-09-30 08:17:52.946207 | controller | networking_mapper : Check for Networking Environment Definition file existence --- 0.04s 2025-09-30 08:17:52.946429 | controller | networking_mapper : Check for Networking Definition file existance ------ 0.04s 2025-09-30 08:17:52.946638 | controller | ci_multus : Gather network layout from OCP host or default networks ----- 0.04s 2025-09-30 08:17:52.946859 | controller | ci_multus : Apply network attachment definition manifests --------------- 0.04s 2025-09-30 08:17:52.947058 | controller | networking_mapper : Load the Networking Definition from file ------------ 0.03s 2025-09-30 08:17:52.947298 | controller | Load shared variables --------------------------------------------------- 0.03s 2025-09-30 08:17:52.947538 | controller | ci_multus : Create the multus namespace --------------------------------- 0.02s 2025-09-30 08:17:53.022597 | controller | INFO Running local > verify 2025-09-30 08:17:53.023163 | controller | INFO Running Ansible Verifier 2025-09-30 08:17:53.528866 | controller | 2025-09-30 08:17:53.528932 | controller | PLAY [Verify] ****************************************************************** 2025-09-30 08:17:53.529060 | controller | 2025-09-30 08:17:53.529209 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:53.529462 | controller | Tuesday 30 September 2025 08:17:53 +0000 (0:00:00.019) 0:00:00.019 ***** 2025-09-30 08:17:55.629917 | controller | ok: [instance] 2025-09-30 08:17:55.629988 | controller | 2025-09-30 08:17:55.630154 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:17:55.630288 | controller | Tuesday 30 September 2025 08:17:55 +0000 (0:00:02.101) 0:00:02.120 ***** 2025-09-30 08:17:55.651929 | controller | ok: [instance] 2025-09-30 08:17:55.652003 | controller | 2025-09-30 08:17:55.652108 | controller | TASK [Fetch files stat results] ************************************************ 2025-09-30 08:17:55.652213 | controller | Tuesday 30 September 2025 08:17:55 +0000 (0:00:00.022) 0:00:02.142 ***** 2025-09-30 08:17:56.062717 | controller | ok: [instance] 2025-09-30 08:17:56.062798 | controller | 2025-09-30 08:17:56.062864 | controller | TASK [Assert that expected file exist] ***************************************** 2025-09-30 08:17:56.062965 | controller | Tuesday 30 September 2025 08:17:56 +0000 (0:00:00.410) 0:00:02.553 ***** 2025-09-30 08:17:56.091717 | controller | ok: [instance] => changed=false 2025-09-30 08:17:56.092231 | controller | msg: All assertions passed 2025-09-30 08:17:56.448969 | controller | 2025-09-30 08:17:56.449016 | controller | TASK [Fetch file content] ****************************************************** 2025-09-30 08:17:56.449027 | controller | Tuesday 30 September 2025 08:17:56 +0000 (0:00:00.029) 0:00:02.582 ***** 2025-09-30 08:17:56.449041 | controller | ok: [instance] 2025-09-30 08:17:56.449069 | controller | 2025-09-30 08:17:56.449141 | controller | TASK [Set _ci_multus_nad variable] ********************************************* 2025-09-30 08:17:56.449270 | controller | Tuesday 30 September 2025 08:17:56 +0000 (0:00:00.356) 0:00:02.938 ***** 2025-09-30 08:17:56.495131 | controller | ok: [instance] 2025-09-30 08:17:56.495195 | controller | 2025-09-30 08:17:56.495360 | controller | TASK [Assert expected number of Network Attachment Definitions are created] **** 2025-09-30 08:17:56.495521 | controller | Tuesday 30 September 2025 08:17:56 +0000 (0:00:00.046) 0:00:02.985 ***** 2025-09-30 08:17:56.568424 | controller | ok: [instance] 2025-09-30 08:17:56.568525 | controller | 2025-09-30 08:17:56.568704 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:56.568738 | controller | instance : ok=7 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:17:56.568959 | controller | 2025-09-30 08:17:56.569614 | controller | Tuesday 30 September 2025 08:17:56 +0000 (0:00:00.074) 0:00:03.059 ***** 2025-09-30 08:17:56.570215 | controller | =============================================================================== 2025-09-30 08:17:56.570255 | controller | Gathering Facts --------------------------------------------------------- 2.10s 2025-09-30 08:17:56.570271 | controller | Fetch files stat results ------------------------------------------------ 0.41s 2025-09-30 08:17:56.570286 | controller | Fetch file content ------------------------------------------------------ 0.36s 2025-09-30 08:17:56.570309 | controller | Assert expected number of Network Attachment Definitions are created ---- 0.07s 2025-09-30 08:17:56.638997 | controller | Set _ci_multus_nad variable --------------------------------------------- 0.05s 2025-09-30 08:17:56.639097 | controller | Assert that expected file exist ----------------------------------------- 0.03s 2025-09-30 08:17:56.639113 | controller | Load shared variables --------------------------------------------------- 0.02s 2025-09-30 08:17:56.639141 | controller | INFO Verifier completed successfully. 2025-09-30 08:17:56.648867 | controller | INFO Running local > side_effect 2025-09-30 08:17:57.167352 | controller | 2025-09-30 08:17:57.167481 | controller | PLAY [Clean] ******************************************************************* 2025-09-30 08:17:57.167503 | controller | 2025-09-30 08:17:57.167774 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:58.277473 | controller | Tuesday 30 September 2025 08:17:57 +0000 (0:00:00.015) 0:00:00.015 ***** 2025-09-30 08:17:58.277632 | controller | ok: [instance] 2025-09-30 08:17:58.277787 | controller | 2025-09-30 08:17:58.277834 | controller | TASK [Backup NAD before cleanup so they can be inspected in CI] **************** 2025-09-30 08:17:58.685331 | controller | Tuesday 30 September 2025 08:17:58 +0000 (0:00:01.110) 0:00:01.126 ***** 2025-09-30 08:17:58.685377 | controller | changed: [instance] 2025-09-30 08:17:58.715323 | controller | 2025-09-30 08:17:58.715346 | controller | TASK [ci_multus : Cleanup - Fetch NADs in namespace: openstack] **************** 2025-09-30 08:17:58.715353 | controller | Tuesday 30 September 2025 08:17:58 +0000 (0:00:00.407) 0:00:01.533 ***** 2025-09-30 08:17:58.715362 | controller | skipping: [instance] 2025-09-30 08:17:58.755535 | controller | 2025-09-30 08:17:58.755586 | controller | TASK [ci_multus : Cleanup - Delete NADs] *************************************** 2025-09-30 08:17:58.755594 | controller | Tuesday 30 September 2025 08:17:58 +0000 (0:00:00.030) 0:00:01.564 ***** 2025-09-30 08:17:58.755607 | controller | skipping: [instance] 2025-09-30 08:17:59.147993 | controller | 2025-09-30 08:17:59.148036 | controller | TASK [ci_multus : Cleanup - Remove if artifact directory exists] *************** 2025-09-30 08:17:59.148044 | controller | Tuesday 30 September 2025 08:17:58 +0000 (0:00:00.039) 0:00:01.603 ***** 2025-09-30 08:17:59.148059 | controller | changed: [instance] 2025-09-30 08:17:59.148154 | controller | 2025-09-30 08:17:59.148320 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:17:59.148526 | controller | instance : ok=3 changed=2 unreachable=0 failed=0 skipped=2 rescued=0 ignored=0 2025-09-30 08:17:59.148665 | controller | 2025-09-30 08:17:59.148860 | controller | Tuesday 30 September 2025 08:17:59 +0000 (0:00:00.393) 0:00:01.997 ***** 2025-09-30 08:17:59.148993 | controller | =============================================================================== 2025-09-30 08:17:59.149135 | controller | Gathering Facts --------------------------------------------------------- 1.11s 2025-09-30 08:17:59.149367 | controller | Backup NAD before cleanup so they can be inspected in CI ---------------- 0.41s 2025-09-30 08:17:59.149544 | controller | ci_multus : Cleanup - Remove if artifact directory exists --------------- 0.39s 2025-09-30 08:17:59.149689 | controller | ci_multus : Cleanup - Delete NADs --------------------------------------- 0.04s 2025-09-30 08:17:59.149831 | controller | ci_multus : Cleanup - Fetch NADs in namespace: openstack ---------------- 0.03s 2025-09-30 08:17:59.248197 | controller | INFO Running local > verify 2025-09-30 08:17:59.248916 | controller | INFO Running Ansible Verifier 2025-09-30 08:17:59.785835 | controller | 2025-09-30 08:17:59.786075 | controller | PLAY [Verify Clean] ************************************************************ 2025-09-30 08:17:59.786567 | controller | 2025-09-30 08:17:59.786899 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:17:59.786923 | controller | Tuesday 30 September 2025 08:17:59 +0000 (0:00:00.016) 0:00:00.016 ***** 2025-09-30 08:18:01.908591 | controller | ok: [instance] 2025-09-30 08:18:01.909087 | controller | 2025-09-30 08:18:01.939889 | controller | TASK [Include default vars] **************************************************** 2025-09-30 08:18:01.939942 | controller | Tuesday 30 September 2025 08:18:01 +0000 (0:00:02.123) 0:00:02.139 ***** 2025-09-30 08:18:01.939957 | controller | ok: [instance] 2025-09-30 08:18:01.939977 | controller | 2025-09-30 08:18:01.939985 | controller | TASK [Fetch file stat results] ************************************************* 2025-09-30 08:18:01.939993 | controller | Tuesday 30 September 2025 08:18:01 +0000 (0:00:00.031) 0:00:02.170 ***** 2025-09-30 08:18:02.291878 | controller | ok: [instance] 2025-09-30 08:18:02.291978 | controller | 2025-09-30 08:18:02.292137 | controller | TASK [Assert that created file are removed by cleanup] ************************* 2025-09-30 08:18:02.292284 | controller | Tuesday 30 September 2025 08:18:02 +0000 (0:00:00.352) 0:00:02.522 ***** 2025-09-30 08:18:02.336442 | controller | ok: [instance] => changed=false 2025-09-30 08:18:02.336531 | controller | msg: All assertions passed 2025-09-30 08:18:02.336672 | controller | 2025-09-30 08:18:02.336829 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:18:02.336990 | controller | instance : ok=4 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:18:02.337113 | controller | 2025-09-30 08:18:02.337270 | controller | Tuesday 30 September 2025 08:18:02 +0000 (0:00:00.045) 0:00:02.567 ***** 2025-09-30 08:18:02.337436 | controller | =============================================================================== 2025-09-30 08:18:02.337558 | controller | Gathering Facts --------------------------------------------------------- 2.12s 2025-09-30 08:18:02.337711 | controller | Fetch file stat results ------------------------------------------------- 0.35s 2025-09-30 08:18:02.337862 | controller | Assert that created file are removed by cleanup ------------------------- 0.05s 2025-09-30 08:18:02.337996 | controller | Include default vars ---------------------------------------------------- 0.03s 2025-09-30 08:18:02.413369 | controller | INFO Verifier completed successfully. 2025-09-30 08:18:02.413779 | controller | INFO Pruning extra files from scenario ephemeral directory 2025-09-30 08:18:02.427245 | controller | INFO Running local_ipv6 > destroy 2025-09-30 08:18:02.427622 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:18:02.438836 | controller | INFO Running local_ipv6 > create 2025-09-30 08:18:02.439841 | controller | WARNING Skipping, instances are delegated. 2025-09-30 08:18:02.448992 | controller | INFO Running local_ipv6 > converge 2025-09-30 08:18:02.917557 | controller | 2025-09-30 08:18:02.917658 | controller | PLAY [Converge] **************************************************************** 2025-09-30 08:18:02.917802 | controller | 2025-09-30 08:18:02.917979 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:18:02.918108 | controller | Tuesday 30 September 2025 08:18:02 +0000 (0:00:00.016) 0:00:00.016 ***** 2025-09-30 08:18:04.006590 | controller | ok: [instance] 2025-09-30 08:18:04.007429 | controller | 2025-09-30 08:18:04.038298 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:18:04.038338 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:01.089) 0:00:01.105 ***** 2025-09-30 08:18:04.038354 | controller | ok: [instance] 2025-09-30 08:18:04.038470 | controller | 2025-09-30 08:18:04.038510 | controller | TASK [Call ci_multus role] ***************************************************** 2025-09-30 08:18:04.038552 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.030) 0:00:01.136 ***** 2025-09-30 08:18:04.086467 | controller | 2025-09-30 08:18:04.086895 | controller | TASK [ci_multus : Create manifests directory] ********************************** 2025-09-30 08:18:04.087135 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.049) 0:00:01.185 ***** 2025-09-30 08:18:04.511923 | controller | changed: [instance] 2025-09-30 08:18:04.512234 | controller | 2025-09-30 08:18:04.512302 | controller | TASK [networking_mapper : Check for Networking Environment Definition file existence] *** 2025-09-30 08:18:04.512317 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.425) 0:00:01.610 ***** 2025-09-30 08:18:04.552274 | controller | skipping: [instance] 2025-09-30 08:18:04.552518 | controller | 2025-09-30 08:18:04.552560 | controller | TASK [networking_mapper : Check for Networking Definition file existance] ****** 2025-09-30 08:18:04.552577 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.040) 0:00:01.650 ***** 2025-09-30 08:18:04.586924 | controller | skipping: [instance] 2025-09-30 08:18:04.587199 | controller | 2025-09-30 08:18:04.587249 | controller | TASK [networking_mapper : Load the Networking Definition from file] ************ 2025-09-30 08:18:04.620574 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.034) 0:00:01.685 ***** 2025-09-30 08:18:04.620637 | controller | skipping: [instance] 2025-09-30 08:18:04.620861 | controller | 2025-09-30 08:18:04.620911 | controller | TASK [networking_mapper : Set cifmw_networking_env_definition is present] ****** 2025-09-30 08:18:04.665813 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.033) 0:00:01.718 ***** 2025-09-30 08:18:04.665865 | controller | skipping: [instance] 2025-09-30 08:18:04.730785 | controller | 2025-09-30 08:18:04.730855 | controller | TASK [ci_multus : Gather network layout from OCP host or default networks] ***** 2025-09-30 08:18:04.730866 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.045) 0:00:01.764 ***** 2025-09-30 08:18:04.730882 | controller | ok: [instance] 2025-09-30 08:18:04.848450 | controller | 2025-09-30 08:18:04.848492 | controller | TASK [ci_multus : Merge any available multus net info patches] ***************** 2025-09-30 08:18:04.848500 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.065) 0:00:01.829 ***** 2025-09-30 08:18:04.848527 | controller | skipping: [instance] => (item={'default': {'interface_name': 'eth1', 'network_name': 'default', 'gw_v6': 'fdc0:8b54:108a:c949:0000:0000:0000:0001', 'network_v6': 'fdc0:8b54:108a:c949::/64', 'tools': {'multus': {'ipv6_ranges': [{'start': 'fdc0:8b54:108a:c949:0000:0000:0000:001e', 'end': 'fdc0:8b54:108a:c949:0000:0000:0000:0027'}]}}}}) 2025-09-30 08:18:04.848552 | controller | skipping: [instance] 2025-09-30 08:18:04.848685 | controller | 2025-09-30 08:18:04.848846 | controller | TASK [ci_multus : Remove any networks without Multus networking defined] ******* 2025-09-30 08:18:04.849000 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.117) 0:00:01.947 ***** 2025-09-30 08:18:04.926803 | controller | ok: [instance] 2025-09-30 08:18:04.926864 | controller | 2025-09-30 08:18:04.926973 | controller | TASK [ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined] *** 2025-09-30 08:18:04.927073 | controller | Tuesday 30 September 2025 08:18:04 +0000 (0:00:00.078) 0:00:02.025 ***** 2025-09-30 08:18:05.017028 | controller | ok: [instance] 2025-09-30 08:18:05.017311 | controller | 2025-09-30 08:18:05.017471 | controller | TASK [ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined] *** 2025-09-30 08:18:05.017581 | controller | Tuesday 30 September 2025 08:18:05 +0000 (0:00:00.089) 0:00:02.115 ***** 2025-09-30 08:18:05.129747 | controller | ok: [instance] 2025-09-30 08:18:05.129840 | controller | 2025-09-30 08:18:05.129984 | controller | TASK [ci_multus : Render NetworkAttachmenktDefinition manifests] *************** 2025-09-30 08:18:05.130011 | controller | Tuesday 30 September 2025 08:18:05 +0000 (0:00:00.113) 0:00:02.228 ***** 2025-09-30 08:18:05.834282 | controller | changed: [instance] 2025-09-30 08:18:05.834345 | controller | 2025-09-30 08:18:05.834373 | controller | TASK [ci_multus : Create the multus namespace] ********************************* 2025-09-30 08:18:05.834524 | controller | Tuesday 30 September 2025 08:18:05 +0000 (0:00:00.704) 0:00:02.933 ***** 2025-09-30 08:18:05.863776 | controller | skipping: [instance] 2025-09-30 08:18:05.863907 | controller | 2025-09-30 08:18:05.864016 | controller | TASK [ci_multus : Apply network attachment definition manifests] *************** 2025-09-30 08:18:05.864125 | controller | Tuesday 30 September 2025 08:18:05 +0000 (0:00:00.028) 0:00:02.961 ***** 2025-09-30 08:18:05.924101 | controller | skipping: [instance] 2025-09-30 08:18:05.924205 | controller | 2025-09-30 08:18:05.924233 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:18:05.925097 | controller | instance : ok=8 changed=2 unreachable=0 failed=0 skipped=7 rescued=0 ignored=0 2025-09-30 08:18:05.925144 | controller | 2025-09-30 08:18:05.925205 | controller | Tuesday 30 September 2025 08:18:05 +0000 (0:00:00.061) 0:00:03.023 ***** 2025-09-30 08:18:05.925227 | controller | =============================================================================== 2025-09-30 08:18:05.925244 | controller | Gathering Facts --------------------------------------------------------- 1.09s 2025-09-30 08:18:05.925272 | controller | ci_multus : Render NetworkAttachmenktDefinition manifests --------------- 0.70s 2025-09-30 08:18:05.925290 | controller | ci_multus : Create manifests directory ---------------------------------- 0.43s 2025-09-30 08:18:05.925307 | controller | ci_multus : Merge any available multus net info patches ----------------- 0.12s 2025-09-30 08:18:05.925324 | controller | ci_multus : Remove any networks in cifmw_ci_multus_deny_list if defined --- 0.11s 2025-09-30 08:18:05.925341 | controller | ci_multus : Remove any networks not in cifmw_ci_multus_allow_list if defined --- 0.09s 2025-09-30 08:18:05.925364 | controller | ci_multus : Remove any networks without Multus networking defined ------- 0.08s 2025-09-30 08:18:05.925493 | controller | ci_multus : Gather network layout from OCP host or default networks ----- 0.07s 2025-09-30 08:18:05.925553 | controller | ci_multus : Apply network attachment definition manifests --------------- 0.06s 2025-09-30 08:18:05.925590 | controller | Call ci_multus role ----------------------------------------------------- 0.05s 2025-09-30 08:18:05.925638 | controller | networking_mapper : Set cifmw_networking_env_definition is present ------ 0.05s 2025-09-30 08:18:05.925762 | controller | networking_mapper : Check for Networking Environment Definition file existence --- 0.04s 2025-09-30 08:18:05.925868 | controller | networking_mapper : Check for Networking Definition file existance ------ 0.03s 2025-09-30 08:18:05.925956 | controller | networking_mapper : Load the Networking Definition from file ------------ 0.03s 2025-09-30 08:18:05.926054 | controller | Load shared variables --------------------------------------------------- 0.03s 2025-09-30 08:18:05.926137 | controller | ci_multus : Create the multus namespace --------------------------------- 0.03s 2025-09-30 08:18:06.059178 | controller | INFO Running local_ipv6 > verify 2025-09-30 08:18:06.059563 | controller | INFO Running Ansible Verifier 2025-09-30 08:18:06.637691 | controller | 2025-09-30 08:18:06.637767 | controller | PLAY [Verify] ****************************************************************** 2025-09-30 08:18:06.637943 | controller | 2025-09-30 08:18:06.638112 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:18:06.638268 | controller | Tuesday 30 September 2025 08:18:06 +0000 (0:00:00.016) 0:00:00.016 ***** 2025-09-30 08:18:07.901228 | controller | ok: [instance] 2025-09-30 08:18:07.901353 | controller | 2025-09-30 08:18:07.901373 | controller | TASK [Load shared variables] *************************************************** 2025-09-30 08:18:07.901416 | controller | Tuesday 30 September 2025 08:18:07 +0000 (0:00:01.263) 0:00:01.279 ***** 2025-09-30 08:18:07.926828 | controller | ok: [instance] 2025-09-30 08:18:07.926881 | controller | 2025-09-30 08:18:07.926890 | controller | TASK [Fetch files stat results] ************************************************ 2025-09-30 08:18:07.926899 | controller | Tuesday 30 September 2025 08:18:07 +0000 (0:00:00.025) 0:00:01.305 ***** 2025-09-30 08:18:08.349140 | controller | ok: [instance] 2025-09-30 08:18:08.349213 | controller | 2025-09-30 08:18:08.349310 | controller | TASK [Assert that expected file exist] ***************************************** 2025-09-30 08:18:08.349445 | controller | Tuesday 30 September 2025 08:18:08 +0000 (0:00:00.422) 0:00:01.727 ***** 2025-09-30 08:18:08.399413 | controller | ok: [instance] => changed=false 2025-09-30 08:18:08.399516 | controller | msg: All assertions passed 2025-09-30 08:18:08.399665 | controller | 2025-09-30 08:18:08.399860 | controller | TASK [Fetch file content] ****************************************************** 2025-09-30 08:18:08.400003 | controller | Tuesday 30 September 2025 08:18:08 +0000 (0:00:00.049) 0:00:01.777 ***** 2025-09-30 08:18:08.811821 | controller | ok: [instance] 2025-09-30 08:18:08.811908 | controller | 2025-09-30 08:18:08.812039 | controller | TASK [Set _ci_multus_nad variable] ********************************************* 2025-09-30 08:18:08.812064 | controller | Tuesday 30 September 2025 08:18:08 +0000 (0:00:00.413) 0:00:02.190 ***** 2025-09-30 08:18:08.847349 | controller | ok: [instance] 2025-09-30 08:18:08.847474 | controller | 2025-09-30 08:18:08.847634 | controller | TASK [Assert expected number of Network Attachment Definitions are created] **** 2025-09-30 08:18:08.847663 | controller | Tuesday 30 September 2025 08:18:08 +0000 (0:00:00.035) 0:00:02.226 ***** 2025-09-30 08:18:08.899322 | controller | ok: [instance] 2025-09-30 08:18:08.899446 | controller | 2025-09-30 08:18:08.899482 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:18:08.899525 | controller | instance : ok=7 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:18:08.899625 | controller | 2025-09-30 08:18:08.899706 | controller | Tuesday 30 September 2025 08:18:08 +0000 (0:00:00.052) 0:00:02.278 ***** 2025-09-30 08:18:08.899817 | controller | =============================================================================== 2025-09-30 08:18:08.899893 | controller | Gathering Facts --------------------------------------------------------- 1.26s 2025-09-30 08:18:08.900010 | controller | Fetch files stat results ------------------------------------------------ 0.42s 2025-09-30 08:18:08.900089 | controller | Fetch file content ------------------------------------------------------ 0.41s 2025-09-30 08:18:08.900189 | controller | Assert expected number of Network Attachment Definitions are created ---- 0.05s 2025-09-30 08:18:08.900308 | controller | Assert that expected file exist ----------------------------------------- 0.05s 2025-09-30 08:18:08.900428 | controller | Set _ci_multus_nad variable --------------------------------------------- 0.04s 2025-09-30 08:18:08.900516 | controller | Load shared variables --------------------------------------------------- 0.03s 2025-09-30 08:18:08.964159 | controller | INFO Verifier completed successfully. 2025-09-30 08:18:08.978618 | controller | INFO Running local_ipv6 > side_effect 2025-09-30 08:18:09.501133 | controller | 2025-09-30 08:18:09.501233 | controller | PLAY [Clean] ******************************************************************* 2025-09-30 08:18:09.501255 | controller | 2025-09-30 08:18:09.501446 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:18:09.501590 | controller | Tuesday 30 September 2025 08:18:09 +0000 (0:00:00.018) 0:00:00.018 ***** 2025-09-30 08:18:10.587900 | controller | ok: [instance] 2025-09-30 08:18:10.588155 | controller | 2025-09-30 08:18:10.588194 | controller | TASK [Backup NAD before cleanup so they can be inspected in CI] **************** 2025-09-30 08:18:10.968767 | controller | Tuesday 30 September 2025 08:18:10 +0000 (0:00:01.087) 0:00:01.106 ***** 2025-09-30 08:18:10.968821 | controller | changed: [instance] 2025-09-30 08:18:10.969166 | controller | 2025-09-30 08:18:10.969188 | controller | TASK [ci_multus : Cleanup - Fetch NADs in namespace: openstack] **************** 2025-09-30 08:18:11.006239 | controller | Tuesday 30 September 2025 08:18:10 +0000 (0:00:00.380) 0:00:01.486 ***** 2025-09-30 08:18:11.006303 | controller | skipping: [instance] 2025-09-30 08:18:11.006532 | controller | 2025-09-30 08:18:11.006570 | controller | TASK [ci_multus : Cleanup - Delete NADs] *************************************** 2025-09-30 08:18:11.006792 | controller | Tuesday 30 September 2025 08:18:11 +0000 (0:00:00.037) 0:00:01.524 ***** 2025-09-30 08:18:11.060467 | controller | skipping: [instance] 2025-09-30 08:18:11.060510 | controller | 2025-09-30 08:18:11.060520 | controller | TASK [ci_multus : Cleanup - Remove if artifact directory exists] *************** 2025-09-30 08:18:11.060531 | controller | Tuesday 30 September 2025 08:18:11 +0000 (0:00:00.053) 0:00:01.577 ***** 2025-09-30 08:18:11.476557 | controller | changed: [instance] 2025-09-30 08:18:11.476650 | controller | 2025-09-30 08:18:11.476965 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:18:11.477071 | controller | instance : ok=3 changed=2 unreachable=0 failed=0 skipped=2 rescued=0 ignored=0 2025-09-30 08:18:11.477270 | controller | 2025-09-30 08:18:11.477470 | controller | Tuesday 30 September 2025 08:18:11 +0000 (0:00:00.417) 0:00:01.995 ***** 2025-09-30 08:18:11.478029 | controller | =============================================================================== 2025-09-30 08:18:11.478144 | controller | Gathering Facts --------------------------------------------------------- 1.09s 2025-09-30 08:18:11.478175 | controller | ci_multus : Cleanup - Remove if artifact directory exists --------------- 0.42s 2025-09-30 08:18:11.478241 | controller | Backup NAD before cleanup so they can be inspected in CI ---------------- 0.38s 2025-09-30 08:18:11.478700 | controller | ci_multus : Cleanup - Delete NADs --------------------------------------- 0.05s 2025-09-30 08:18:11.556534 | controller | ci_multus : Cleanup - Fetch NADs in namespace: openstack ---------------- 0.04s 2025-09-30 08:18:11.556573 | controller | INFO Running local_ipv6 > verify 2025-09-30 08:18:11.556886 | controller | INFO Running Ansible Verifier 2025-09-30 08:18:12.085771 | controller | 2025-09-30 08:18:12.086019 | controller | PLAY [Verify Clean] ************************************************************ 2025-09-30 08:18:12.086164 | controller | 2025-09-30 08:18:12.086344 | controller | TASK [Gathering Facts] ********************************************************* 2025-09-30 08:18:12.086530 | controller | Tuesday 30 September 2025 08:18:12 +0000 (0:00:00.016) 0:00:00.016 ***** 2025-09-30 08:18:13.193244 | controller | ok: [instance] 2025-09-30 08:18:13.193295 | controller | 2025-09-30 08:18:13.193306 | controller | TASK [Include default vars] **************************************************** 2025-09-30 08:18:13.193420 | controller | Tuesday 30 September 2025 08:18:13 +0000 (0:00:01.107) 0:00:01.124 ***** 2025-09-30 08:18:13.225771 | controller | ok: [instance] 2025-09-30 08:18:13.225837 | controller | 2025-09-30 08:18:13.225864 | controller | TASK [Fetch file stat results] ************************************************* 2025-09-30 08:18:13.226003 | controller | Tuesday 30 September 2025 08:18:13 +0000 (0:00:00.032) 0:00:01.156 ***** 2025-09-30 08:18:13.584005 | controller | ok: [instance] 2025-09-30 08:18:13.584188 | controller | 2025-09-30 08:18:13.584497 | controller | TASK [Assert that created file are removed by cleanup] ************************* 2025-09-30 08:18:13.584777 | controller | Tuesday 30 September 2025 08:18:13 +0000 (0:00:00.357) 0:00:01.514 ***** 2025-09-30 08:18:13.642865 | controller | ok: [instance] => changed=false 2025-09-30 08:18:13.642998 | controller | msg: All assertions passed 2025-09-30 08:18:13.643194 | controller | 2025-09-30 08:18:13.643436 | controller | PLAY RECAP ********************************************************************* 2025-09-30 08:18:13.643615 | controller | instance : ok=4 changed=0 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0 2025-09-30 08:18:13.643776 | controller | 2025-09-30 08:18:13.643969 | controller | Tuesday 30 September 2025 08:18:13 +0000 (0:00:00.060) 0:00:01.574 ***** 2025-09-30 08:18:13.644184 | controller | =============================================================================== 2025-09-30 08:18:13.644369 | controller | Gathering Facts --------------------------------------------------------- 1.11s 2025-09-30 08:18:13.644548 | controller | Fetch file stat results ------------------------------------------------- 0.36s 2025-09-30 08:18:13.644685 | controller | Assert that created file are removed by cleanup ------------------------- 0.06s 2025-09-30 08:18:13.644863 | controller | Include default vars ---------------------------------------------------- 0.03s 2025-09-30 08:18:13.711203 | controller | INFO Verifier completed successfully. 2025-09-30 08:18:13.711798 | controller | INFO Pruning extra files from scenario ephemeral directory 2025-09-30 08:18:13.714270 | controller | INFO Writing /tmp/report.html report. 2025-09-30 08:18:13.852938 | controller | changed 2025-09-30 08:18:13.895197 | 2025-09-30 08:18:13.895282 | PLAY RECAP 2025-09-30 08:18:13.895333 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-30 08:18:13.895364 | 2025-09-30 08:18:14.004014 | RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/molecule-test.yml@main] 2025-09-30 08:18:14.004892 | POST-RUN START: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main] 2025-09-30 08:18:14.579510 | 2025-09-30 08:18:14.579620 | PLAY [Run ci/playbooks/collect-logs.yml] 2025-09-30 08:18:14.601442 | 2025-09-30 08:18:14.601536 | TASK [Filter out host if needed] 2025-09-30 08:18:14.610720 | controller | skipping: end_host conditional evaluated to False, continuing execution for controller 2025-09-30 08:18:14.615429 | 2025-09-30 08:18:14.615492 | TASK [Ensure file is present] 2025-09-30 08:18:15.129672 | controller | ok 2025-09-30 08:18:15.143296 | 2025-09-30 08:18:15.143454 | TASK [Manage molecule report file] 2025-09-30 08:18:15.711229 | controller | changed 2025-09-30 08:18:15.717277 | 2025-09-30 08:18:15.717374 | TASK [Check if we get ci-framework-data basedir] 2025-09-30 08:18:16.091502 | controller | ok 2025-09-30 08:18:16.104276 | 2025-09-30 08:18:16.104415 | TASK [Create ci-framework-data log directory for zuul] 2025-09-30 08:18:16.665042 | controller | changed 2025-09-30 08:18:16.677905 | 2025-09-30 08:18:16.678045 | TASK [Copy ci-framework interesting files] 2025-09-30 08:18:17.043825 | controller | cp: cannot stat '/home/zuul/ci-framework-data/tests': No such file or directory 2025-09-30 08:18:17.225356 | controller | changed 2025-09-30 08:18:17.237152 | 2025-09-30 08:18:17.237298 | TASK [Get SELinux listing] 2025-09-30 08:18:17.794193 | controller | changed 2025-09-30 08:18:17.807293 | 2025-09-30 08:18:17.807473 | TASK [Generate log index] 2025-09-30 08:18:19.347540 | controller | changed 2025-09-30 08:18:19.359497 | 2025-09-30 08:18:19.359661 | TASK [Get some env related data] 2025-09-30 08:18:20.101855 | controller | /home/zuul/.local/bin/ansible 2025-09-30 08:18:20.913469 | controller | changed 2025-09-30 08:18:20.965106 | 2025-09-30 08:18:20.965285 | TASK [Generate list of logs to collect in home directory] 2025-09-30 08:18:21.425072 | controller | ok: All paths examined 2025-09-30 08:18:21.431533 | 2025-09-30 08:18:21.431642 | LOOP [Copy logs from home directory] 2025-09-30 08:18:22.250180 | controller | changed: 2025-09-30 08:18:22.250498 | controller | { 2025-09-30 08:18:22.250541 | controller | "atime": 1743544925.4788878, 2025-09-30 08:18:22.250568 | controller | "ctime": 1743545329.1409318, 2025-09-30 08:18:22.250594 | controller | "dev": 64513, 2025-09-30 08:18:22.250619 | controller | "gid": 1000, 2025-09-30 08:18:22.250646 | controller | "gr_name": "zuul", 2025-09-30 08:18:22.250673 | controller | "inode": 4518807, 2025-09-30 08:18:22.250764 | controller | "isblk": false, 2025-09-30 08:18:22.250793 | controller | "ischr": false, 2025-09-30 08:18:22.250819 | controller | "isdir": false, 2025-09-30 08:18:22.250843 | controller | "isfifo": false, 2025-09-30 08:18:22.250868 | controller | "isgid": false, 2025-09-30 08:18:22.250892 | controller | "islnk": false, 2025-09-30 08:18:22.250917 | controller | "isreg": true, 2025-09-30 08:18:22.250940 | controller | "issock": false, 2025-09-30 08:18:22.250963 | controller | "isuid": false, 2025-09-30 08:18:22.250988 | controller | "mode": "0644", 2025-09-30 08:18:22.251012 | controller | "mtime": 1743545329.1409318, 2025-09-30 08:18:22.251037 | controller | "nlink": 1, 2025-09-30 08:18:22.251062 | controller | "path": "/home/zuul/crc-setup.log", 2025-09-30 08:18:22.251091 | controller | "pw_name": "zuul", 2025-09-30 08:18:22.251118 | controller | "rgrp": true, 2025-09-30 08:18:22.251143 | controller | "roth": true, 2025-09-30 08:18:22.251169 | controller | "rusr": true, 2025-09-30 08:18:22.251194 | controller | "size": 4108, 2025-09-30 08:18:22.251219 | controller | "uid": 1000, 2025-09-30 08:18:22.251243 | controller | "wgrp": false, 2025-09-30 08:18:22.251267 | controller | "woth": false, 2025-09-30 08:18:22.251294 | controller | "wusr": true, 2025-09-30 08:18:22.251319 | controller | "xgrp": false, 2025-09-30 08:18:22.251343 | controller | "xoth": false, 2025-09-30 08:18:22.251366 | controller | "xusr": false 2025-09-30 08:18:22.251390 | controller | } 2025-09-30 08:18:23.062623 | controller | changed: 2025-09-30 08:18:23.064728 | controller | { 2025-09-30 08:18:23.064787 | controller | "atime": 1759219541.0127778, 2025-09-30 08:18:23.064819 | controller | "ctime": 1759219538.7237191, 2025-09-30 08:18:23.064845 | controller | "dev": 64513, 2025-09-30 08:18:23.064869 | controller | "gid": 1000, 2025-09-30 08:18:23.064894 | controller | "gr_name": "zuul", 2025-09-30 08:18:23.064919 | controller | "inode": 4194437, 2025-09-30 08:18:23.064944 | controller | "isblk": false, 2025-09-30 08:18:23.064967 | controller | "ischr": false, 2025-09-30 08:18:23.064990 | controller | "isdir": false, 2025-09-30 08:18:23.065013 | controller | "isfifo": false, 2025-09-30 08:18:23.065036 | controller | "isgid": false, 2025-09-30 08:18:23.065059 | controller | "islnk": false, 2025-09-30 08:18:23.065082 | controller | "isreg": true, 2025-09-30 08:18:23.065107 | controller | "issock": false, 2025-09-30 08:18:23.065131 | controller | "isuid": false, 2025-09-30 08:18:23.065164 | controller | "mode": "0644", 2025-09-30 08:18:23.065188 | controller | "mtime": 1759219538.7237191, 2025-09-30 08:18:23.065210 | controller | "nlink": 1, 2025-09-30 08:18:23.065234 | controller | "path": "/home/zuul/crc-start.log", 2025-09-30 08:18:23.065256 | controller | "pw_name": "zuul", 2025-09-30 08:18:23.065280 | controller | "rgrp": true, 2025-09-30 08:18:23.065303 | controller | "roth": true, 2025-09-30 08:18:23.065325 | controller | "rusr": true, 2025-09-30 08:18:23.065348 | controller | "size": 3404, 2025-09-30 08:18:23.065372 | controller | "uid": 1000, 2025-09-30 08:18:23.065395 | controller | "wgrp": false, 2025-09-30 08:18:23.065416 | controller | "woth": false, 2025-09-30 08:18:23.065439 | controller | "wusr": true, 2025-09-30 08:18:23.065462 | controller | "xgrp": false, 2025-09-30 08:18:23.065486 | controller | "xoth": false, 2025-09-30 08:18:23.065510 | controller | "xusr": false 2025-09-30 08:18:23.065533 | controller | } 2025-09-30 08:18:23.881739 | controller | changed: 2025-09-30 08:18:23.881907 | controller | { 2025-09-30 08:18:23.881970 | controller | "atime": 1759220169.2509928, 2025-09-30 08:18:23.882020 | controller | "ctime": 1759220185.3874063, 2025-09-30 08:18:23.882068 | controller | "dev": 64513, 2025-09-30 08:18:23.882115 | controller | "gid": 1000, 2025-09-30 08:18:23.882161 | controller | "gr_name": "zuul", 2025-09-30 08:18:23.882211 | controller | "inode": 4685804, 2025-09-30 08:18:23.882256 | controller | "isblk": false, 2025-09-30 08:18:23.882299 | controller | "ischr": false, 2025-09-30 08:18:23.882343 | controller | "isdir": false, 2025-09-30 08:18:23.882386 | controller | "isfifo": false, 2025-09-30 08:18:23.882429 | controller | "isgid": false, 2025-09-30 08:18:23.882471 | controller | "islnk": false, 2025-09-30 08:18:23.882516 | controller | "isreg": true, 2025-09-30 08:18:23.882561 | controller | "issock": false, 2025-09-30 08:18:23.888613 | controller | "isuid": false, 2025-09-30 08:18:23.888722 | controller | "mode": "0644", 2025-09-30 08:18:23.888765 | controller | "mtime": 1759220185.3874063, 2025-09-30 08:18:23.888802 | controller | "nlink": 1, 2025-09-30 08:18:23.888839 | controller | "path": "/home/zuul/ansible.log", 2025-09-30 08:18:23.888875 | controller | "pw_name": "zuul", 2025-09-30 08:18:23.888912 | controller | "rgrp": true, 2025-09-30 08:18:23.888946 | controller | "roth": true, 2025-09-30 08:18:23.888993 | controller | "rusr": true, 2025-09-30 08:18:23.889030 | controller | "size": 6749, 2025-09-30 08:18:23.889064 | controller | "uid": 1000, 2025-09-30 08:18:23.889098 | controller | "wgrp": false, 2025-09-30 08:18:23.889130 | controller | "woth": false, 2025-09-30 08:18:23.889163 | controller | "wusr": true, 2025-09-30 08:18:23.889195 | controller | "xgrp": false, 2025-09-30 08:18:23.889228 | controller | "xoth": false, 2025-09-30 08:18:23.889260 | controller | "xusr": false 2025-09-30 08:18:23.889292 | controller | } 2025-09-30 08:18:23.912956 | 2025-09-30 08:18:23.913137 | TASK [Copy crio stats log file] 2025-09-30 08:18:23.950106 | controller | skipping: Conditional result was False 2025-09-30 08:18:23.971128 | 2025-09-30 08:18:23.971454 | TASK [Get SELinux related data] 2025-09-30 08:18:24.395218 | controller | 2025-09-30 08:18:24.528340 | controller | ERROR 2025-09-30 08:18:24.528648 | controller | { 2025-09-30 08:18:24.528767 | controller | "delta": "0:00:00.018432", 2025-09-30 08:18:24.528812 | controller | "end": "2025-09-30 08:18:24.397052", 2025-09-30 08:18:24.528851 | controller | "msg": "non-zero return code", 2025-09-30 08:18:24.528886 | controller | "rc": 1, 2025-09-30 08:18:24.528921 | controller | "start": "2025-09-30 08:18:24.378620" 2025-09-30 08:18:24.528955 | controller | } 2025-09-30 08:18:24.529002 | controller | ERROR: Ignoring Errors 2025-09-30 08:18:24.541106 | 2025-09-30 08:18:24.541288 | TASK [Create system configuration directory] 2025-09-30 08:18:24.885954 | controller | changed 2025-09-30 08:18:24.897865 | 2025-09-30 08:18:24.898027 | TASK [Get some of the system configurations] 2025-09-30 08:18:25.452296 | controller | changed 2025-09-30 08:18:25.464407 | 2025-09-30 08:18:25.464578 | TASK [Copy generated documentation if available] 2025-09-30 08:18:25.492390 | controller | skipping: Conditional result was False 2025-09-30 08:18:25.505613 | 2025-09-30 08:18:25.505844 | TASK [Copy generated AsciiDoc documentation if available] 2025-09-30 08:18:25.533161 | controller | skipping: Conditional result was False 2025-09-30 08:18:25.546182 | 2025-09-30 08:18:25.546362 | TASK [Compress logs bigger than 2MB] 2025-09-30 08:18:26.097491 | controller | changed 2025-09-30 08:18:26.109774 | 2025-09-30 08:18:26.109949 | TASK [Copy files from workspace on node] 2025-09-30 08:18:26.139300 | controller | ok 2025-09-30 08:18:26.194175 | 2025-09-30 08:18:26.194324 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-30 08:18:26.219821 | controller | skipping: Conditional result was False 2025-09-30 08:18:26.228547 | 2025-09-30 08:18:26.228737 | TASK [fetch-output : Set log path for single node] 2025-09-30 08:18:26.274943 | controller | ok 2025-09-30 08:18:26.287052 | 2025-09-30 08:18:26.287246 | LOOP [fetch-output : Ensure local output dirs] 2025-09-30 08:18:26.559996 | controller -> localhost | ok: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/logs" 2025-09-30 08:18:26.560484 | controller -> localhost | changed: All items complete 2025-09-30 08:18:26.560569 | 2025-09-30 08:18:26.779188 | controller -> localhost | changed: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/artifacts" 2025-09-30 08:18:26.997748 | controller -> localhost | changed: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/docs" 2025-09-30 08:18:27.019719 | 2025-09-30 08:18:27.019877 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-30 08:18:27.846287 | controller | changed: 2025-09-30 08:18:27.846545 | controller | .d..t...... ./ 2025-09-30 08:18:27.846581 | controller | >f+++++++++ README.html 2025-09-30 08:18:27.846602 | controller | >f+++++++++ ansible-execution.log 2025-09-30 08:18:27.846621 | controller | >f+++++++++ ansible.log 2025-09-30 08:18:27.846640 | controller | >f+++++++++ crc-setup.log 2025-09-30 08:18:27.846657 | controller | >f+++++++++ crc-start.log 2025-09-30 08:18:27.846674 | controller | >f+++++++++ dmesg.log 2025-09-30 08:18:27.846738 | controller | >f+++++++++ installed-pkgs.log 2025-09-30 08:18:27.846759 | controller | >f+++++++++ python.log 2025-09-30 08:18:27.846776 | controller | >f+++++++++ registries.conf 2025-09-30 08:18:27.846792 | controller | >f+++++++++ report.html 2025-09-30 08:18:27.846808 | controller | >f+++++++++ selinux-denials.log 2025-09-30 08:18:27.846823 | controller | >f+++++++++ selinux-listing.log 2025-09-30 08:18:27.846839 | controller | cd+++++++++ ci-framework-data/ 2025-09-30 08:18:27.846855 | controller | cd+++++++++ ci-framework-data/artifacts/ 2025-09-30 08:18:27.846873 | controller | >f+++++++++ ci-framework-data/artifacts/zuul_inventory.yml 2025-09-30 08:18:27.846889 | controller | cd+++++++++ ci-framework-data/artifacts/manifests/ 2025-09-30 08:18:27.846907 | controller | cd+++++++++ ci-framework-data/artifacts/manifests/ci_multus.backup/ 2025-09-30 08:18:27.846923 | controller | cd+++++++++ ci-framework-data/artifacts/manifests/ci_multus.backup/ci_multus/ 2025-09-30 08:18:27.846939 | controller | >f+++++++++ ci-framework-data/artifacts/manifests/ci_multus.backup/ci_multus/ci_multus_nads.yml 2025-09-30 08:18:27.846955 | controller | cd+++++++++ ci-framework-data/artifacts/parameters/ 2025-09-30 08:18:27.846971 | controller | >f+++++++++ ci-framework-data/artifacts/parameters/zuul-params.yml 2025-09-30 08:18:27.846987 | controller | cd+++++++++ ci-framework-data/logs/ 2025-09-30 08:18:27.847004 | controller | >f+++++++++ ci-framework-data/logs/molecule-execution.log 2025-09-30 08:18:27.847020 | controller | cd+++++++++ registries.conf.d/ 2025-09-30 08:18:27.847036 | controller | >f+++++++++ registries.conf.d/000-shortnames.conf 2025-09-30 08:18:27.847058 | controller | cd+++++++++ system-config/ 2025-09-30 08:18:27.847075 | controller | cd+++++++++ system-config/libvirt/ 2025-09-30 08:18:27.847091 | controller | >f+++++++++ system-config/libvirt/libvirt-admin.conf 2025-09-30 08:18:27.847106 | controller | >f+++++++++ system-config/libvirt/libvirt.conf 2025-09-30 08:18:27.847122 | controller | >f+++++++++ system-config/libvirt/libvirtd.conf 2025-09-30 08:18:27.847137 | controller | >f+++++++++ system-config/libvirt/network.conf 2025-09-30 08:18:27.847152 | controller | >f+++++++++ system-config/libvirt/qemu-lockd.conf 2025-09-30 08:18:27.847167 | controller | >f+++++++++ system-config/libvirt/qemu.conf 2025-09-30 08:18:27.847182 | controller | >f+++++++++ system-config/libvirt/virtinterfaced.conf 2025-09-30 08:18:27.847198 | controller | >f+++++++++ system-config/libvirt/virtlockd.conf 2025-09-30 08:18:27.847213 | controller | >f+++++++++ system-config/libvirt/virtlogd.conf 2025-09-30 08:18:27.847228 | controller | >f+++++++++ system-config/libvirt/virtnetworkd.conf 2025-09-30 08:18:27.847243 | controller | >f+++++++++ system-config/libvirt/virtnodedevd.conf 2025-09-30 08:18:27.847258 | controller | >f+++++++++ system-config/libvirt/virtnwfilterd.conf 2025-09-30 08:18:27.847273 | controller | >f+++++++++ system-config/libvirt/virtproxyd.conf 2025-09-30 08:18:27.847289 | controller | >f+++++++++ system-config/libvirt/virtqemud.conf 2025-09-30 08:18:27.847304 | controller | >f+++++++++ system-config/libvirt/virtsecretd.conf 2025-09-30 08:18:27.847319 | controller | >f+++++++++ system-config/libvirt/virtstoraged.conf 2025-09-30 08:18:28.450758 | controller | changed: .d..t...... ./ 2025-09-30 08:18:29.077085 | controller | changed: .d..t...... ./ 2025-09-30 08:18:29.092512 | 2025-09-30 08:18:29.092609 | TASK [Return artifact to Zuul] 2025-09-30 08:18:29.132334 | controller | ok 2025-09-30 08:18:29.151655 | 2025-09-30 08:18:29.151751 | PLAY [Run ci/playbooks/collect-logs.yml on CRC host] 2025-09-30 08:18:29.151845 | 2025-09-30 08:18:29.151870 | PLAY RECAP 2025-09-30 08:18:29.151904 | controller | ok: 18 changed: 13 unreachable: 0 failed: 0 skipped: 4 rescued: 0 ignored: 1 2025-09-30 08:18:29.151922 | 2025-09-30 08:18:29.260638 | POST-RUN END RESULT_NORMAL: [untrusted : github.com/openstack-k8s-operators/ci-framework/ci/playbooks/collect-logs.yml@main] 2025-09-30 08:18:29.262574 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/dlrn/dlrn-report.yaml@master] 2025-09-30 08:18:29.859961 | 2025-09-30 08:18:29.860069 | PLAY [Report DLRN results after job run] 2025-09-30 08:18:29.880457 | 2025-09-30 08:18:29.880549 | TASK [Report job status to DLRN] 2025-09-30 08:18:29.900010 | controller | ok 2025-09-30 08:18:29.923084 | 2025-09-30 08:18:29.923173 | TASK [dlrn_report : Warning if DLRN is not running] 2025-09-30 08:18:29.988108 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.001128 | 2025-09-30 08:18:30.001270 | TASK [dlrn_report : Install dlrnapi-client shyaml package] 2025-09-30 08:18:30.049869 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.063986 | 2025-09-30 08:18:30.064140 | TASK [dlrn_report : Install kinit related package] 2025-09-30 08:18:30.122554 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.135629 | 2025-09-30 08:18:30.135808 | TASK [dlrn_report : Install dlrn kerberos related packages] 2025-09-30 08:18:30.194663 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.210002 | 2025-09-30 08:18:30.210139 | TASK [Set zuul-log-path fact] 2025-09-30 08:18:30.258598 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.272530 | 2025-09-30 08:18:30.272731 | TASK [dlrn_report : Set the the value of cifmw_repo_setup_promotion when multiple dlrn tags are used] 2025-09-30 08:18:30.321803 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.334946 | 2025-09-30 08:18:30.335088 | TASK [Get hash related data from repo_setup role] 2025-09-30 08:18:30.384207 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.398903 | 2025-09-30 08:18:30.399109 | TASK [dlrn_report : Perform kinit for DLRN kerberos authentication] 2025-09-30 08:18:30.950305 | controller | skipping: Conditional result was False 2025-09-30 08:18:30.962993 | 2025-09-30 08:18:30.963189 | TASK [dlrn_report : Set empty value for dlrnapi password] 2025-09-30 08:18:31.041555 | controller | skipping: Conditional result was False 2025-09-30 08:18:31.054807 | 2025-09-30 08:18:31.054999 | TASK [dlrn_report : Report results to dlrn for the tested hash] 2025-09-30 08:18:31.607802 | controller | skipping: Conditional result was False 2025-09-30 08:18:31.660527 | 2025-09-30 08:18:31.660759 | PLAY RECAP 2025-09-30 08:18:31.660829 | controller | ok: 0 changed: 0 unreachable: 0 failed: 0 skipped: 10 rescued: 0 ignored: 0 2025-09-30 08:18:31.660859 | 2025-09-30 08:18:31.766570 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/ci-framework-rdo-base/dlrn/dlrn-report.yaml@master] 2025-09-30 08:18:31.768442 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 08:18:32.387754 | 2025-09-30 08:18:32.387887 | PLAY [all] 2025-09-30 08:18:32.407136 | 2025-09-30 08:18:32.407265 | TASK [include_role : fetch-output] 2025-09-30 08:18:32.456969 | controller | ok 2025-09-30 08:18:32.474430 | 2025-09-30 08:18:32.474571 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-30 08:18:32.549917 | controller | skipping: Conditional result was False 2025-09-30 08:18:32.556448 | 2025-09-30 08:18:32.556530 | TASK [fetch-output : Set log path for single node] 2025-09-30 08:18:32.612441 | controller | ok 2025-09-30 08:18:32.623980 | 2025-09-30 08:18:32.624192 | LOOP [fetch-output : Ensure local output dirs] 2025-09-30 08:18:33.071421 | controller -> localhost | ok: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/logs" 2025-09-30 08:18:33.330914 | controller -> localhost | ok: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/artifacts" 2025-09-30 08:18:33.603027 | controller -> localhost | ok: "/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/docs" 2025-09-30 08:18:33.629201 | 2025-09-30 08:18:33.629441 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-30 08:18:34.541525 | controller | ok 2025-09-30 08:18:34.541993 | controller | ok: All items complete 2025-09-30 08:18:34.542051 | 2025-09-30 08:18:35.208382 | controller | ok 2025-09-30 08:18:35.790193 | controller | ok 2025-09-30 08:18:35.816993 | 2025-09-30 08:18:35.817266 | TASK [include_role : fetch-output-openshift] 2025-09-30 08:18:35.843799 | controller | skipping: Conditional result was False 2025-09-30 08:18:35.856592 | 2025-09-30 08:18:35.856793 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-30 08:18:36.367992 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012875 2025-09-30 08:18:36.653036 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.010677 2025-09-30 08:18:36.691507 | 2025-09-30 08:18:36.691708 | PLAY [all] 2025-09-30 08:18:36.707603 | 2025-09-30 08:18:36.707715 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-09-30 08:18:37.251955 | controller | changed 2025-09-30 08:18:37.301709 | 2025-09-30 08:18:37.301811 | PLAY RECAP 2025-09-30 08:18:37.301871 | controller | ok: 5 changed: 2 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 08:18:37.301898 | 2025-09-30 08:18:37.451799 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 08:18:37.452894 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-09-30 08:18:38.075566 | 2025-09-30 08:18:38.075709 | PLAY [localhost] 2025-09-30 08:18:38.093765 | 2025-09-30 08:18:38.093851 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-30 08:18:38.536174 | localhost | changed 2025-09-30 08:18:38.548255 | 2025-09-30 08:18:38.548442 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-30 08:18:38.584212 | localhost | ok 2025-09-30 08:18:38.603711 | 2025-09-30 08:18:38.603869 | TASK [add-fileserver : Create SSH private key tempfile] 2025-09-30 08:18:39.072812 | localhost | changed 2025-09-30 08:18:39.085310 | 2025-09-30 08:18:39.085581 | TASK [add-fileserver : Create SSH private key from secret] 2025-09-30 08:18:39.850998 | localhost | changed 2025-09-30 08:18:39.862991 | 2025-09-30 08:18:39.863137 | TASK [add-fileserver : Add fileserver ssh key] 2025-09-30 08:18:40.311117 | localhost | Identity added: /var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/tmp/ansible.k_pud9h0 (/var/lib/zuul/builds/544f8b65120048bdb921b8e39f7a1ea3/work/tmp/ansible.k_pud9h0) 2025-09-30 08:18:40.311560 | localhost | ok: Runtime: 0:00:00.014654 2025-09-30 08:18:40.322389 | 2025-09-30 08:18:40.322543 | TASK [add-fileserver : Remove SSH private key from disk] 2025-09-30 08:18:40.675062 | localhost | ok: Runtime: 0:00:00.012116 2025-09-30 08:18:40.681441 | 2025-09-30 08:18:40.681571 | TASK [add-fileserver : Add fileserver to inventory] 2025-09-30 08:18:40.770919 | localhost | changed 2025-09-30 08:18:40.781663 | 2025-09-30 08:18:40.782157 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-09-30 08:18:41.262118 | localhost | changed 2025-09-30 08:18:41.306419 | 2025-09-30 08:18:41.306580 | PLAY [localhost] 2025-09-30 08:18:41.325010 | 2025-09-30 08:18:41.325104 | TASK [Generate bulk log download script] 2025-09-30 08:18:41.349144 | localhost | ok 2025-09-30 08:18:41.365990 | 2025-09-30 08:18:41.366087 | TASK [local-log-download : Check API endpoint is defined] 2025-09-30 08:18:41.417233 | localhost | ok: All assertions passed 2025-09-30 08:18:41.423617 | 2025-09-30 08:18:41.423726 | TASK [local-log-download : Create download script] 2025-09-30 08:18:41.874729 | localhost -> localhost | changed 2025-09-30 08:18:41.884822 | 2025-09-30 08:18:41.884914 | TASK [Register quick-download link] 2025-09-30 08:18:41.941152 | localhost | ok 2025-09-30 08:18:41.961772 | 2025-09-30 08:18:41.961844 | PLAY [logserver.rdoproject.org] 2025-09-30 08:18:41.971290 | 2025-09-30 08:18:41.971350 | TASK [Set zuul-log-path fact] 2025-09-30 08:18:41.987131 | logserver.rdoproject.org | ok 2025-09-30 08:18:41.995789 | 2025-09-30 08:18:41.995852 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 08:18:42.022218 | logserver.rdoproject.org | ok 2025-09-30 08:18:42.027632 | 2025-09-30 08:18:42.027711 | TASK [upload-logs : Create log directories] 2025-09-30 08:18:42.915635 | logserver.rdoproject.org | changed 2025-09-30 08:18:42.922385 | 2025-09-30 08:18:42.922532 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-09-30 08:18:43.286714 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.009177 2025-09-30 08:18:43.296510 | 2025-09-30 08:18:43.296664 | TASK [upload-logs : Upload logs to log server] 2025-09-30 08:18:44.065183 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-09-30 08:18:44.071358 | 2025-09-30 08:18:44.071487 | LOOP [upload-logs : Compress console log and json output] 2025-09-30 08:18:44.148968 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 08:18:44.161217 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 08:18:44.177666 | 2025-09-30 08:18:44.177841 | LOOP [upload-logs : Upload compressed console log and json output] 2025-09-30 08:18:44.248058 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 08:18:44.248518 | 2025-09-30 08:18:44.253585 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 08:18:44.267144 | 2025-09-30 08:18:44.267368 | LOOP [upload-logs : Upload console log and json output]