2026-11-09 03:20:25,381 - INFO - Domain Default found not creating 2026-11-09 03:20:25,585 - INFO - Project ctest-TestQos-56698252 not found, creating it 2026-11-09 03:20:26,295 - INFO - Created Project:ctest-TestQos-56698252, ID : e3e66c1a-3d8f-4007-b833-3ef1c133bea9 2026-11-09 03:20:29,052 - DEBUG - Response for create_network : {'network': {'id': '56d6dedb-ca27-4725-b696-39bc0f5a6c47', 'name': 'ctest-vn-96161533', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'tags': [], 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-56698252', 'ctest-vn-96161533'], 'port_security_enabled': True, 'description': ''}} 2026-11-09 03:20:29,404 - DEBUG - Response for create_subnet : {'subnet': {'id': 'f4de0d28-d3bb-49f7-abda-2ae0f6b57b41', 'name': '', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'network_id': '56d6dedb-ca27-4725-b696-39bc0f5a6c47', 'ip_version': 4, 'cidr': '113.18.163.192/26', 'allocation_pools': [{'start': '113.18.163.194', 'end': '113.18.163.254'}], 'gateway_ip': '113.18.163.193', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '113.18.163.194', 'tags': [], 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9'}} 2026-11-09 03:20:29,663 - DEBUG - Response for create_subnet : {'subnet': {'id': 'c999e989-038d-4832-850a-4721a84b7fe1', 'name': '', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'network_id': '56d6dedb-ca27-4725-b696-39bc0f5a6c47', 'ip_version': 6, 'cidr': '2288:a698:f636:7a7b:eaf2:fc46::/96', 'allocation_pools': [{'start': '2288:a698:f636:7a7b:eaf2:fc46:0:2', 'end': '2288:a698:f636:7a7b:eaf2:fc46:ffff:fffe'}], 'gateway_ip': '2288:a698:f636:7a7b:eaf2:fc46:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '2288:a698:f636:7a7b:eaf2:fc46:0:2', 'tags': [], 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9'}} 2026-11-09 03:20:29,691 - INFO - Created VN ctest-vn-96161533 2026-11-09 03:20:29,704 - DEBUG - VN ctest-vn-96161533 UUID is 56d6dedb-ca27-4725-b696-39bc0f5a6c47 2026-11-09 03:20:30,152 - DEBUG - Response for create_network : {'network': {'id': '6876de5b-43dc-4fb8-bc68-ab7e0adeeb51', 'name': 'ctest-vn-32964103', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'tags': [], 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestQos-56698252', 'ctest-vn-32964103'], 'port_security_enabled': True, 'description': ''}} 2026-11-09 03:20:30,437 - DEBUG - Response for create_subnet : {'subnet': {'id': '0db621fd-a40c-4e65-9b7d-63ff57ba70fc', 'name': '', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'network_id': '6876de5b-43dc-4fb8-bc68-ab7e0adeeb51', 'ip_version': 4, 'cidr': '191.33.131.0/26', 'allocation_pools': [{'start': '191.33.131.2', 'end': '191.33.131.62'}], 'gateway_ip': '191.33.131.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '191.33.131.2', 'tags': [], 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9'}} 2026-11-09 03:20:30,624 - DEBUG - Response for create_subnet : {'subnet': {'id': '680b43a8-60f7-4b06-9825-6cd92d635644', 'name': '', 'tenant_id': 'e3e66c1a3d8f4007b8333ef1c133bea9', 'network_id': '6876de5b-43dc-4fb8-bc68-ab7e0adeeb51', 'ip_version': 6, 'cidr': '394d:53df:474c:78f5:3552:83ab::/96', 'allocation_pools': [{'start': '394d:53df:474c:78f5:3552:83ab:0:2', 'end': '394d:53df:474c:78f5:3552:83ab:ffff:fffe'}], 'gateway_ip': '394d:53df:474c:78f5:3552:83ab:0:1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '394d:53df:474c:78f5:3552:83ab:0:2', 'tags': [], 'project_id': 'e3e66c1a3d8f4007b8333ef1c133bea9'}} 2026-11-09 03:20:30,650 - INFO - Created VN ctest-vn-32964103 2026-11-09 03:20:30,662 - DEBUG - VN ctest-vn-32964103 UUID is 6876de5b-43dc-4fb8-bc68-ab7e0adeeb51 2026-11-09 03:20:30,901 - DEBUG - Services list from nova: [, , , ] 2026-11-09 03:20:31,499 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6500-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6500-1) 2026-11-09 03:20:32,170 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6500-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6500-2) 2026-11-09 03:20:32,847 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-6500-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-6500-2) 2026-11-09 03:20:32,847 - INFO - Waiting for VM ctest-TestQos-56698252-46017145 to be up.. 2026-11-09 03:20:32,907 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:20:38,004 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:20:43,098 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:20:48,192 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:20:53,302 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:20:58,398 - DEBUG - VM is in ACTIVE state now 2026-11-09 03:20:58,398 - INFO - VM name : ctest-TestQos-56698252-46017145 2026-11-09 03:20:58,499 - DEBUG - VM ctest-TestQos-56698252-46017145 ID is 86cff534-9e22-4f63-b01f-b34d4c851510 2026-11-09 03:20:58,533 - DEBUG - VM ctest-TestQos-56698252-46017145 launched on Node an-jenkins-deploy-platform-ansible-os-6500-1 2026-11-09 03:20:58,637 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine/86cff534-9e22-4f63-b01f-b34d4c851510 2026-11-09 03:20:59,018 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine/86cff534-9e22-4f63-b01f-b34d4c851510 2026-11-09 03:20:59,056 - DEBUG - Requesting: http://10.0.0.33:8082/virtual-machine-interface/5ee18653-820a-4b4e-aee7-9b92a5512fbc 2026-11-09 03:21:02,231 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1009ms') 2026-11-09 03:21:02,231 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:02,246 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:02,246 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:06,332 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1014ms') 2026-11-09 03:21:06,332 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:06,347 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:06,348 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:10,427 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1014ms') 2026-11-09 03:21:10,427 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:10,445 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:10,445 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:14,521 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1009ms') 2026-11-09 03:21:14,521 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:14,538 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:14,538 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:18,615 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1013ms') 2026-11-09 03:21:18,615 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:18,630 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:18,630 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:22,715 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1014ms') 2026-11-09 03:21:22,715 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:22,730 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:22,730 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:26,811 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1016ms') 2026-11-09 03:21:26,811 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:26,829 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:26,829 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:30,907 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1009ms') 2026-11-09 03:21:30,907 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:30,923 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:30,923 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:34,995 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1013ms') 2026-11-09 03:21:34,995 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 failed! 2026-11-09 03:21:35,011 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 113.18.163.193 and allocation pool is NOT set 2026-11-09 03:21:35,011 - DEBUG - Gateway for vn default-domain:ctest-TestQos-56698252:ctest-vn-96161533 is 2288:a698:f636:7a7b:eaf2:fc46:0:1 and allocation pool is NOT set 2026-11-09 03:21:37,080 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=7.28 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=6.85 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 6.852/7.064/7.276/0.212 ms') 2026-11-09 03:21:37,080 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestQos-56698252-46017145 passed 2026-11-09 03:21:37,155 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2026-11-09 03:21:37,155 - DEBUG - Waiting to SSH to VM ctest-TestQos-56698252-46017145, IP 113.18.163.195, Port 22 2026-11-09 03:21:37,223 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused /bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''} 2026-11-09 03:21:37,355 - DEBUG - VM ctest-TestQos-56698252-46017145 is NOT ready for SSH connections, VM status: ACTIVE 2026-11-09 03:21:42,357 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2026-11-09 03:21:42,357 - DEBUG - Waiting to SSH to VM ctest-TestQos-56698252-46017145, IP 113.18.163.195, Port 22 2026-11-09 03:21:42,423 - DEBUG - Error on ssh to ubuntu@169.254.0.3:22, result: /bin/bash: connect: Connection refused /bin/bash: line 1: /dev/tcp/169.254.0.3/22: Connection refused {'failed': True, 'command': '(echo > /dev/tcp/169.254.0.3/22)', 'real_command': '/bin/bash -l -c "(echo > /dev/tcp/169.254.0.3/22)"', 'return_code': 1, 'succeeded': False, 'stderr': ''} 2026-11-09 03:21:42,519 - DEBUG - VM ctest-TestQos-56698252-46017145 is NOT ready for SSH connections, VM status: ACTIVE 2026-11-09 03:21:47,520 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2026-11-09 03:21:47,520 - DEBUG - Waiting to SSH to VM ctest-TestQos-56698252-46017145, IP 113.18.163.195, Port 22 2026-11-09 03:21:47,695 - DEBUG - VM ctest-TestQos-56698252-46017145 is ready for SSH connections 2026-11-09 03:21:47,695 - INFO - Waiting for VM ctest-TestQos-56698252-46709262 to be up.. 2026-11-09 03:21:47,806 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:21:52,902 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:21:58,002 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:03,105 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:08,213 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:13,313 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:18,431 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:23,545 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:28,635 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:33,724 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:38,841 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:43,932 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:49,026 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:54,121 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:22:59,228 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:04,344 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:09,440 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:14,542 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:19,690 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:24,786 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:29,886 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:34,986 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:40,080 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:45,175 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:50,270 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:23:55,371 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:00,512 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:05,607 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:10,725 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:15,818 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:20,967 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2026-11-09 03:24:20,968 - ERROR - VM is not in ACTIVE state 2026-11-09 03:24:21,667 - DEBUG - VM console log not formed yet 2026-11-09 03:24:21,668 - DEBUG - None 2026-11-09 03:24:21,668 - ERROR - VM ctest-TestQos-56698252-46709262 has not booted 2026-11-09 03:24:21,668 - INFO - Deleting VM ctest-TestQos-56698252-46017145 2026-11-09 03:24:21,754 - INFO - Skip interface_detach for VM ctest-TestQos-56698252-46709262 in state BUILD 2026-11-09 03:24:21,754 - INFO - Deleting VM ctest-TestQos-56698252-46709262 2026-11-09 03:24:21,823 - INFO - Skip interface_detach for VM ctest-TestQos-56698252-24291141 in state BUILD 2026-11-09 03:24:21,824 - INFO - Deleting VM ctest-TestQos-56698252-24291141 2026-11-09 03:24:21,824 - ERROR - VM ctest-TestQos-56698252-24291141 has failed to come up 2026-11-09 03:24:21,824 - ERROR - Nova failed to get host of the VM 2026-11-09 03:24:21,824 - ERROR - VM ctest-TestQos-56698252-24291141 has failed to come up 2026-11-09 03:24:21,824 - ERROR - Nova failed to get host of the VM