2025-09-11 03:09:24,591 - INFO - Domain Default found not creating 2025-09-11 03:09:24,784 - INFO - Project ctest-TestSubInterfaces-07309185 not found, creating it 2025-09-11 03:09:25,303 - INFO - Created Project:ctest-TestSubInterfaces-07309185, ID : ea985260-3bc6-4bda-bb74-707dfa448a87 2025-09-11 03:09:27,548 - DEBUG - Response for create_network : {'network': {'id': '19dd77ad-1d22-4de1-8f1b-0f003a1b4641', 'name': 'ctest-vn-54456714', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'project_id': 'ea9852603bc64bdabb74707dfa448a87', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vn-54456714'], 'port_security_enabled': True, 'description': ''}} 2025-09-11 03:09:27,831 - DEBUG - Response for create_subnet : {'subnet': {'id': '385320fd-a6eb-4547-8723-bf054128ced7', 'name': '', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': '19dd77ad-1d22-4de1-8f1b-0f003a1b4641', 'ip_version': 4, 'cidr': '46.99.203.0/26', 'allocation_pools': [{'start': '46.99.203.2', 'end': '46.99.203.62'}], 'gateway_ip': '46.99.203.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '46.99.203.2', 'tags': [], 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:27,854 - INFO - Created VN ctest-vn-54456714 2025-09-11 03:09:27,866 - DEBUG - VN ctest-vn-54456714 UUID is 19dd77ad-1d22-4de1-8f1b-0f003a1b4641 2025-09-11 03:09:28,205 - DEBUG - Response for create_network : {'network': {'id': 'd8861b2c-7d6d-462e-90bc-79276bab677d', 'name': 'ctest-vn-70967626', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'project_id': 'ea9852603bc64bdabb74707dfa448a87', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vn-70967626'], 'port_security_enabled': True, 'description': ''}} 2025-09-11 03:09:28,490 - DEBUG - Response for create_subnet : {'subnet': {'id': 'c2f45cc5-a101-4b3a-9e27-53bfa3a51830', 'name': '', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': 'd8861b2c-7d6d-462e-90bc-79276bab677d', 'ip_version': 4, 'cidr': '162.210.149.0/26', 'allocation_pools': [{'start': '162.210.149.2', 'end': '162.210.149.62'}], 'gateway_ip': '162.210.149.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '162.210.149.2', 'tags': [], 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:28,512 - INFO - Created VN ctest-vn-70967626 2025-09-11 03:09:28,525 - DEBUG - VN ctest-vn-70967626 UUID is d8861b2c-7d6d-462e-90bc-79276bab677d 2025-09-11 03:09:28,901 - DEBUG - Response for create_network : {'network': {'id': '19dd4d38-6597-4b76-aea3-82cb1ec7840b', 'name': 'ctest-vn-03788557', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'project_id': 'ea9852603bc64bdabb74707dfa448a87', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vn-03788557'], 'port_security_enabled': True, 'description': ''}} 2025-09-11 03:09:29,182 - DEBUG - Response for create_subnet : {'subnet': {'id': '891d1c33-7d07-46c7-b845-a14ba0e374d7', 'name': '', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': '19dd4d38-6597-4b76-aea3-82cb1ec7840b', 'ip_version': 4, 'cidr': '142.3.247.64/26', 'allocation_pools': [{'start': '142.3.247.66', 'end': '142.3.247.126'}], 'gateway_ip': '142.3.247.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '142.3.247.66', 'tags': [], 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:29,204 - INFO - Created VN ctest-vn-03788557 2025-09-11 03:09:29,215 - DEBUG - VN ctest-vn-03788557 UUID is 19dd4d38-6597-4b76-aea3-82cb1ec7840b 2025-09-11 03:09:29,289 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-87109867']} 2025-09-11 03:09:29,537 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-87109867', 'id': '04c91979-1302-4b7f-9d76-3635d0215758', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': 'd8861b2c-7d6d-462e-90bc-79276bab677d', 'mac_address': '02:04:c9:19:79:13', 'binding:vnic_type': 'normal', 'binding:vif_details': {'port_filter': True}, 'binding:vif_type': 'unbound', 'binding:host_id': None, 'allowed_address_pairs': [], 'fixed_ips': [{'ip_address': '162.210.149.3', 'subnet_id': 'c2f45cc5-a101-4b3a-9e27-53bfa3a51830'}], 'security_groups': ['16535b4e-4d0e-4629-b09c-8f92dada3cbe'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:29,537 - DEBUG - Created port 04c91979-1302-4b7f-9d76-3635d0215758 2025-09-11 03:09:29,611 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-83387556']} 2025-09-11 03:09:30,047 - DEBUG - Created port e676236c-68dc-4755-b4e9-0c0d1353a4c6 2025-09-11 03:09:30,163 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-45798683']} 2025-09-11 03:09:30,452 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-45798683', 'id': '38afdc27-ec6b-4eb1-b067-232b7e1ea02f', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': 'd8861b2c-7d6d-462e-90bc-79276bab677d', 'mac_address': '02:38:af:dc:27:ec', 'binding:vnic_type': 'normal', 'binding:vif_details': {'port_filter': True}, 'binding:vif_type': 'unbound', 'binding:host_id': None, 'allowed_address_pairs': [], 'fixed_ips': [{'ip_address': '162.210.149.4', 'subnet_id': 'c2f45cc5-a101-4b3a-9e27-53bfa3a51830'}], 'security_groups': ['16535b4e-4d0e-4629-b09c-8f92dada3cbe'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:30,452 - DEBUG - Created port 38afdc27-ec6b-4eb1-b067-232b7e1ea02f 2025-09-11 03:09:30,519 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-05383806']} 2025-09-11 03:09:30,951 - DEBUG - Created port e2c39989-5894-44c8-acd0-244d94b4c223 2025-09-11 03:09:31,067 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-67315488']} 2025-09-11 03:09:31,397 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-67315488', 'id': '9ff32872-5788-4d00-9862-f3904b741cbe', 'tenant_id': 'ea9852603bc64bdabb74707dfa448a87', 'network_id': 'd8861b2c-7d6d-462e-90bc-79276bab677d', 'mac_address': '02:9f:f3:28:72:57', 'binding:vnic_type': 'normal', 'binding:vif_details': {'port_filter': True}, 'binding:vif_type': 'unbound', 'binding:host_id': None, 'allowed_address_pairs': [], 'fixed_ips': [{'ip_address': '162.210.149.5', 'subnet_id': 'c2f45cc5-a101-4b3a-9e27-53bfa3a51830'}], 'security_groups': ['16535b4e-4d0e-4629-b09c-8f92dada3cbe'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': 'ea9852603bc64bdabb74707dfa448a87'}} 2025-09-11 03:09:31,397 - DEBUG - Created port 9ff32872-5788-4d00-9862-f3904b741cbe 2025-09-11 03:09:31,467 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-07309185', 'ctest-vmi-88048736']} 2025-09-11 03:09:31,915 - DEBUG - Created port afc05491-eac0-4a6d-900e-9b234c5b41a3 2025-09-11 03:09:32,025 - INFO - ================================================================================ 2025-09-11 03:09:32,025 - INFO - STARTING TEST : test_vlan_interface_2 2025-09-11 03:09:32,025 - INFO - TEST DESCRIPTION : Test ping/hping between tagged-untagged vmis across VNs 2025-09-11 03:09:33,298 - DEBUG - Nothing to compare xmpp stats {'10.0.0.254': {'10.20.0.17': '0', '10.20.0.25': '0'}, '10.0.0.19': {'10.20.0.17': '0', '10.20.0.25': '0'}} with 2025-09-11 03:09:33,298 - INFO - Initial checks done. Running the testcase now 2025-09-11 03:09:33,298 - INFO - 2025-09-11 03:09:33,476 - DEBUG - Services list from nova: [, , , ] 2025-09-11 03:09:34,009 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4079-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4079-1) 2025-09-11 03:09:35,393 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4079-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4079-2) 2025-09-11 03:09:36,087 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4079-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4079-1) 2025-09-11 03:09:36,194 - INFO - Adding interface with subnet_id 385320fd-a6eb-4547-8723-bf054128ced7, port_id None to router 624d4807-df57-40e2-8aaa-93fc5322b90c 2025-09-11 03:09:36,518 - INFO - Adding interface with subnet_id 891d1c33-7d07-46c7-b845-a14ba0e374d7, port_id None to router 624d4807-df57-40e2-8aaa-93fc5322b90c 2025-09-11 03:09:36,952 - INFO - Waiting for VM ctest-TestSubInterfaces-07309185-65564489 to be up.. 2025-09-11 03:09:37,060 - DEBUG - VM is in ACTIVE state now 2025-09-11 03:09:37,060 - INFO - VM name : ctest-TestSubInterfaces-07309185-65564489 2025-09-11 03:09:37,155 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 ID is 02f85105-bf7e-4880-9405-7b250f14fd60 2025-09-11 03:09:37,181 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 launched on Node an-jenkins-deploy-platform-ansible-os-4079-1 2025-09-11 03:09:37,284 - DEBUG - Requesting: http://10.0.0.49:8082/virtual-machine/02f85105-bf7e-4880-9405-7b250f14fd60 2025-09-11 03:09:37,600 - DEBUG - Requesting: http://10.0.0.49:8082/virtual-machine/02f85105-bf7e-4880-9405-7b250f14fd60 2025-09-11 03:09:37,635 - DEBUG - Requesting: http://10.0.0.49:8082/virtual-machine-interface/04c91979-1302-4b7f-9d76-3635d0215758 2025-09-11 03:09:40,849 - 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 1026ms') 2025-09-11 03:09:40,850 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:09:40,863 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:09:44,951 - 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 1019ms') 2025-09-11 03:09:44,952 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:09:44,967 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:09:49,038 - 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 1005ms') 2025-09-11 03:09:49,038 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:09:49,054 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:09:53,141 - 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 1017ms') 2025-09-11 03:09:53,141 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:09:53,159 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:09:57,234 - 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') 2025-09-11 03:09:57,234 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:09:57,249 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:01,329 - 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 1015ms') 2025-09-11 03:10:01,329 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:01,344 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:05,422 - 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 1015ms') 2025-09-11 03:10:05,422 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:05,449 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:09,514 - 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 1006ms') 2025-09-11 03:10:09,514 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:09,528 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:13,616 - 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 1021ms') 2025-09-11 03:10:13,616 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:13,630 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:17,707 - 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 1019ms') 2025-09-11 03:10:17,708 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:17,723 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:21,805 - 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 1027ms') 2025-09-11 03:10:21,805 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 failed! 2025-09-11 03:10:21,819 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-07309185:ctest-vn-70967626 is 162.210.149.1 and allocation pool is NOT set 2025-09-11 03:10:23,878 - 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=5.97 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.668 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 = 0.668/3.319/5.970/2.651 ms') 2025-09-11 03:10:23,878 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-07309185-65564489 passed 2025-09-11 03:10:23,950 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-09-11 03:10:23,950 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-07309185-65564489, IP 162.210.149.3, Port 22 2025-09-11 03:10:24,017 - 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': ''} 2025-09-11 03:10:24,111 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 is NOT ready for SSH connections, VM status: ACTIVE 2025-09-11 03:10:29,112 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-09-11 03:10:29,112 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-07309185-65564489, IP 162.210.149.3, Port 22 2025-09-11 03:10:29,178 - 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': ''} 2025-09-11 03:10:29,262 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 is NOT ready for SSH connections, VM status: ACTIVE 2025-09-11 03:10:34,263 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-09-11 03:10:34,263 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-07309185-65564489, IP 162.210.149.3, Port 22 2025-09-11 03:10:34,334 - 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': ''} 2025-09-11 03:10:34,437 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 is NOT ready for SSH connections, VM status: ACTIVE 2025-09-11 03:10:39,438 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-09-11 03:10:39,438 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-07309185-65564489, IP 162.210.149.3, Port 22 2025-09-11 03:10:39,505 - 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': ''} 2025-09-11 03:10:39,587 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 is NOT ready for SSH connections, VM status: ACTIVE 2025-09-11 03:10:44,587 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-09-11 03:10:44,587 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-07309185-65564489, IP 162.210.149.3, Port 22 2025-09-11 03:10:44,757 - DEBUG - VM ctest-TestSubInterfaces-07309185-65564489 is ready for SSH connections 2025-09-11 03:10:44,758 - INFO - Waiting for VM ctest-TestSubInterfaces-07309185-11850767 to be up.. 2025-09-11 03:10:44,819 - DEBUG - VM is in ERROR state now 2025-09-11 03:10:44,819 - ERROR - VM in error state. 2025-09-11 03:10:44,819 - ERROR - VM is not in ACTIVE state 2025-09-11 03:10:44,901 - ERROR - Fatal Nova Exception while getting VM detail 2025-09-11 03:10:44,901 - DEBUG - None 2025-09-11 03:10:44,902 - INFO - Deleting interface with subnet_id 891d1c33-7d07-46c7-b845-a14ba0e374d7, port_id None from router 624d4807-df57-40e2-8aaa-93fc5322b90c 2025-09-11 03:10:45,142 - INFO - Deleting interface with subnet_id 385320fd-a6eb-4547-8723-bf054128ced7, port_id None from router 624d4807-df57-40e2-8aaa-93fc5322b90c 2025-09-11 03:10:45,416 - INFO - Skip interface_detach for VM ctest-TestSubInterfaces-07309185-81027361 in state BUILD 2025-09-11 03:10:45,417 - INFO - Deleting VM ctest-TestSubInterfaces-07309185-81027361 2025-09-11 03:10:45,417 - ERROR - VM ctest-TestSubInterfaces-07309185-81027361 has failed to come up 2025-09-11 03:10:45,417 - ERROR - Nova failed to get host of the VM 2025-09-11 03:10:45,417 - ERROR - VM ctest-TestSubInterfaces-07309185-81027361 has failed to come up 2025-09-11 03:10:45,417 - ERROR - Nova failed to get host of the VM 2025-09-11 03:10:45,524 - INFO - Skip interface_detach for VM ctest-TestSubInterfaces-07309185-11850767 in state ERROR 2025-09-11 03:10:45,524 - INFO - Deleting VM ctest-TestSubInterfaces-07309185-11850767 2025-09-11 03:10:45,524 - ERROR - VM ctest-TestSubInterfaces-07309185-11850767 has failed to come up 2025-09-11 03:10:45,524 - ERROR - Fault seen in nova show is: {'code': 500, 'created': '2025-09-11T03:09:35Z', 'message': 'No valid host was found. ', 'details': 'Traceback (most recent call last):\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/conductor/manager.py", line 1581, in schedule_and_build_instances\n instance_uuids, return_alternates=True)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/conductor/manager.py", line 942, in _schedule_instances\n return_alternates=return_alternates)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/scheduler/client/query.py", line 42, in select_destinations\n instance_uuids, return_objects, return_alternates)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/scheduler/rpcapi.py", line 160, in select_destinations\n return cctxt.call(ctxt, \'select_destinations\', **msg_args)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 192, in call\n retry=self.retry, transport_options=self.transport_options)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/transport.py", line 128, in _send\n transport_options=transport_options)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 691, in send\n transport_options=transport_options)\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 681, in _send\n raise result\nnova.exception_Remote.NoValidHost_Remote: No valid host was found. \nTraceback (most recent call last):\n\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 241, in inner\n return func(*args, **kwargs)\n\n File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/scheduler/manager.py", line 209, in select_destinations\n raise exception.NoValidHost(reason="")\n\nnova.exception.NoValidHost: No valid host was found. \n\n'} 2025-09-11 03:10:45,524 - INFO - Detaching port 04c91979-1302-4b7f-9d76-3635d0215758 from VM ctest-TestSubInterfaces-07309185-65564489 2025-09-11 03:10:45,564 - INFO - Deleting VM ctest-TestSubInterfaces-07309185-65564489 2025-09-11 03:10:46,980 - ERROR - AssertionError Python 3.9.21: /usr/bin/python3 Thu Sep 11 03:10:44 2025 A problem occurred in a Python script. Here is the sequence of function calls leading up to the error, in the order they occurred. /contrail-test/tcutils/wrappers.py in wrapper(self=, *args=(), **kwargs={}) 78 log.info('Initial checks done. Running the testcase now') 79 log.info('') 80 result = function(self, *args, **kwargs) 81 if self.inputs.upgrade: 82 pid = os.getpid() result = None function = self = args = () kwargs = {} /contrail-test/scripts/vrouter/test_subinterfaces.py in test_vlan_interface_2(self=) 117 118 assert vm1_fixture.wait_till_vm_is_up() 119 assert vm2_fixture.wait_till_vm_is_up() 120 assert vm3_fixture.wait_till_vm_is_up() 121 vm2_fixture = vm2_fixture.wait_till_vm_is_up = > AssertionError: __cause__ = None __class__ = __context__ = None __delattr__ = __dict__ = {} __dir__ = __doc__ = 'Assertion failed.' __eq__ = __format__ = __ge__ = __getattribute__ = __gt__ = __hash__ = __init__ = __init_subclass__ = __le__ = __lt__ = __ne__ = __new__ = __reduce__ = __reduce_ex__ = __repr__ = __setattr__ = __setstate__ = __sizeof__ = __str__ = __subclasshook__ = __suppress_context__ = False __traceback__ = args = () with_traceback = The above is a description of an error in a Python program. Here is the original traceback: Traceback (most recent call last): File "/contrail-test/tcutils/wrappers.py", line 80, in wrapper result = function(self, *args, **kwargs) File "/contrail-test/scripts/vrouter/test_subinterfaces.py", line 119, in test_vlan_interface_2 assert vm2_fixture.wait_till_vm_is_up() AssertionError 2025-09-11 03:10:46,992 - DEBUG - No XMPP flaps were noticed during the test 2025-09-11 03:10:46,992 - INFO -
2025-09-11 03:10:46,992 - INFO - END TEST : test_vlan_interface_2 : FAILED[0:01:14]
2025-09-11 03:10:46,992 - INFO - -------------------------------------------------------------------------------- 2025-09-11 03:10:47,150 - INFO - Deleted port afc05491-eac0-4a6d-900e-9b234c5b41a3 2025-09-11 03:10:47,326 - DEBUG - Response for delete_port : () 2025-09-11 03:10:47,326 - INFO - Deleted port 9ff32872-5788-4d00-9862-f3904b741cbe 2025-09-11 03:10:47,442 - INFO - Deleted port e2c39989-5894-44c8-acd0-244d94b4c223 2025-09-11 03:10:47,600 - DEBUG - Response for delete_port : () 2025-09-11 03:10:47,600 - INFO - Deleted port 38afdc27-ec6b-4eb1-b067-232b7e1ea02f 2025-09-11 03:10:47,782 - INFO - Deleted port e676236c-68dc-4755-b4e9-0c0d1353a4c6 2025-09-11 03:10:48,008 - DEBUG - Response for delete_port : () 2025-09-11 03:10:48,008 - INFO - Deleted port 04c91979-1302-4b7f-9d76-3635d0215758 2025-09-11 03:10:48,008 - INFO - Deleting VN ctest-vn-03788557 2025-09-11 03:10:48,197 - DEBUG - Response for deleting network () 2025-09-11 03:10:48,197 - INFO - Deleting VN ctest-vn-70967626 2025-09-11 03:10:48,349 - DEBUG - Response for deleting network () 2025-09-11 03:10:48,349 - INFO - Deleting VN ctest-vn-54456714 2025-09-11 03:10:48,497 - DEBUG - Response for deleting network () 2025-09-11 03:10:49,214 - INFO - Deleted project: ctest-TestSubInterfaces-07309185, ID : ea985260-3bc6-4bda-bb74-707dfa448a87