2025-11-13 03:35:17,447 - INFO - Domain Default found not creating 2025-11-13 03:35:17,588 - INFO - Project ctest-TestSubInterfaces-40108125 not found, creating it 2025-11-13 03:35:18,084 - INFO - Created Project:ctest-TestSubInterfaces-40108125, ID : 0c73bec4-e401-4afa-942f-02c1f22183be 2025-11-13 03:35:20,371 - DEBUG - Response for create_network : {'network': {'id': '74bce181-5f7d-4704-8a35-ef76095ac1d9', 'name': 'ctest-vn-30882035', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'project_id': '0c73bec4e4014afa942f02c1f22183be', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vn-30882035'], 'port_security_enabled': True, 'description': ''}} 2025-11-13 03:35:20,640 - DEBUG - Response for create_subnet : {'subnet': {'id': '5c6c3c66-595c-4ac2-9c1e-b96a1a0e9029', 'name': '', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '74bce181-5f7d-4704-8a35-ef76095ac1d9', 'ip_version': 4, 'cidr': '90.49.145.64/26', 'allocation_pools': [{'start': '90.49.145.66', 'end': '90.49.145.126'}], 'gateway_ip': '90.49.145.65', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '90.49.145.66', 'tags': [], 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:20,661 - INFO - Created VN ctest-vn-30882035 2025-11-13 03:35:20,673 - DEBUG - VN ctest-vn-30882035 UUID is 74bce181-5f7d-4704-8a35-ef76095ac1d9 2025-11-13 03:35:21,005 - DEBUG - Response for create_network : {'network': {'id': '0788c6ef-99e6-4520-83d5-4f314a7d2396', 'name': 'ctest-vn-53386141', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'project_id': '0c73bec4e4014afa942f02c1f22183be', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vn-53386141'], 'port_security_enabled': True, 'description': ''}} 2025-11-13 03:35:21,294 - DEBUG - Response for create_subnet : {'subnet': {'id': '1e19a6f5-c984-4230-9bef-8559d63cd822', 'name': '', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '0788c6ef-99e6-4520-83d5-4f314a7d2396', 'ip_version': 4, 'cidr': '26.58.133.0/26', 'allocation_pools': [{'start': '26.58.133.2', 'end': '26.58.133.62'}], 'gateway_ip': '26.58.133.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '26.58.133.2', 'tags': [], 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:21,319 - INFO - Created VN ctest-vn-53386141 2025-11-13 03:35:21,331 - DEBUG - VN ctest-vn-53386141 UUID is 0788c6ef-99e6-4520-83d5-4f314a7d2396 2025-11-13 03:35:21,671 - DEBUG - Response for create_network : {'network': {'id': '9a2a2597-364c-421a-a227-7bc7d7fdb272', 'name': 'ctest-vn-87394230', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'project_id': '0c73bec4e4014afa942f02c1f22183be', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vn-87394230'], 'port_security_enabled': True, 'description': ''}} 2025-11-13 03:35:21,879 - DEBUG - Response for create_subnet : {'subnet': {'id': '407297a8-d309-454e-aaf6-6a69d98e75f8', 'name': '', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '9a2a2597-364c-421a-a227-7bc7d7fdb272', 'ip_version': 4, 'cidr': '56.240.27.0/26', 'allocation_pools': [{'start': '56.240.27.2', 'end': '56.240.27.62'}], 'gateway_ip': '56.240.27.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '56.240.27.2', 'tags': [], 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:21,900 - INFO - Created VN ctest-vn-87394230 2025-11-13 03:35:21,909 - DEBUG - VN ctest-vn-87394230 UUID is 9a2a2597-364c-421a-a227-7bc7d7fdb272 2025-11-13 03:35:21,977 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-88472700']} 2025-11-13 03:35:22,282 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-88472700', 'id': 'c55e5860-cfd9-402d-84e2-cb8a05fa5d0c', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '0788c6ef-99e6-4520-83d5-4f314a7d2396', 'mac_address': '02:c5:5e:58:60:cf', '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': '26.58.133.3', 'subnet_id': '1e19a6f5-c984-4230-9bef-8559d63cd822'}], 'security_groups': ['6762280f-65b8-49e3-a5e3-3b4fd659163a'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:22,282 - DEBUG - Created port c55e5860-cfd9-402d-84e2-cb8a05fa5d0c 2025-11-13 03:35:22,351 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-30051079']} 2025-11-13 03:35:22,815 - DEBUG - Created port e168248c-0b6b-4d10-a0c9-a7aa960e3b1a 2025-11-13 03:35:22,923 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-35083679']} 2025-11-13 03:35:23,209 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-35083679', 'id': '5b74fd60-96ef-430c-9125-0f2518abdc56', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '0788c6ef-99e6-4520-83d5-4f314a7d2396', 'mac_address': '02:5b:74:fd:60:96', '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': '26.58.133.4', 'subnet_id': '1e19a6f5-c984-4230-9bef-8559d63cd822'}], 'security_groups': ['6762280f-65b8-49e3-a5e3-3b4fd659163a'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:23,209 - DEBUG - Created port 5b74fd60-96ef-430c-9125-0f2518abdc56 2025-11-13 03:35:23,278 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-11840895']} 2025-11-13 03:35:23,691 - DEBUG - Created port 413afa3f-49a1-4119-bc6e-e9ef03b1826d 2025-11-13 03:35:23,804 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-88531109']} 2025-11-13 03:35:24,111 - DEBUG - Response for create_port : {'port': {'name': 'ctest-vmi-88531109', 'id': 'cbe3d5e7-5102-44f6-bb63-87e77eb874a1', 'tenant_id': '0c73bec4e4014afa942f02c1f22183be', 'network_id': '0788c6ef-99e6-4520-83d5-4f314a7d2396', 'mac_address': '02:cb:e3:d5:e7:51', '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': '26.58.133.5', 'subnet_id': '1e19a6f5-c984-4230-9bef-8559d63cd822'}], 'security_groups': ['6762280f-65b8-49e3-a5e3-3b4fd659163a'], 'admin_state_up': True, 'device_id': '', 'device_owner': '', 'status': 'DOWN', 'port_security_enabled': True, 'description': '', 'project_id': '0c73bec4e4014afa942f02c1f22183be'}} 2025-11-13 03:35:24,111 - DEBUG - Created port cbe3d5e7-5102-44f6-bb63-87e77eb874a1 2025-11-13 03:35:24,180 - DEBUG - Read virtual machine interface {'fq_name': ['default-domain', 'ctest-TestSubInterfaces-40108125', 'ctest-vmi-19713148']} 2025-11-13 03:35:24,603 - DEBUG - Created port 5f23b6b4-a4d7-43f6-a35a-a9cded22a643 2025-11-13 03:35:24,725 - INFO - ================================================================================ 2025-11-13 03:35:24,726 - INFO - STARTING TEST : test_vlan_interface_2 2025-11-13 03:35:24,726 - INFO - TEST DESCRIPTION : Test ping/hping between tagged-untagged vmis across VNs 2025-11-13 03:35:25,987 - DEBUG - Nothing to compare xmpp stats {'10.0.0.19': {'10.20.0.25': '0', '10.20.0.254': '0'}, '10.0.0.23': {'10.20.0.25': '0', '10.20.0.193': '0'}} with 2025-11-13 03:35:25,987 - INFO - Initial checks done. Running the testcase now 2025-11-13 03:35:25,987 - INFO - 2025-11-13 03:35:26,044 - DEBUG - Services list from nova: [, , , ] 2025-11-13 03:35:26,468 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4712-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4712-2) 2025-11-13 03:35:27,733 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4712-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4712-1) 2025-11-13 03:35:28,714 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-4712-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-4712-2) 2025-11-13 03:35:28,903 - INFO - Adding interface with subnet_id 5c6c3c66-595c-4ac2-9c1e-b96a1a0e9029, port_id None to router e06a1971-f3e3-47c3-a5ff-673f7f3dc784 2025-11-13 03:35:29,251 - INFO - Adding interface with subnet_id 407297a8-d309-454e-aaf6-6a69d98e75f8, port_id None to router e06a1971-f3e3-47c3-a5ff-673f7f3dc784 2025-11-13 03:35:29,644 - INFO - Waiting for VM ctest-TestSubInterfaces-40108125-53445697 to be up.. 2025-11-13 03:35:29,788 - DEBUG - VM is in ACTIVE state now 2025-11-13 03:35:29,788 - INFO - VM name : ctest-TestSubInterfaces-40108125-53445697 2025-11-13 03:35:29,931 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 ID is ebd5fc81-2926-4300-9b9a-1615de7e05f5 2025-11-13 03:35:29,975 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 launched on Node an-jenkins-deploy-platform-ansible-os-4712-2 2025-11-13 03:35:30,072 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine/ebd5fc81-2926-4300-9b9a-1615de7e05f5 2025-11-13 03:35:30,413 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine/ebd5fc81-2926-4300-9b9a-1615de7e05f5 2025-11-13 03:35:30,450 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine-interface/c55e5860-cfd9-402d-84e2-cb8a05fa5d0c 2025-11-13 03:35:33,673 - 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 1030ms') 2025-11-13 03:35:33,673 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:33,686 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:37,777 - 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 1025ms') 2025-11-13 03:35:37,777 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:37,793 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:41,871 - 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 1010ms') 2025-11-13 03:35:41,871 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:41,886 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:45,970 - 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-11-13 03:35:45,970 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:45,984 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:50,059 - 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-11-13 03:35:50,059 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:50,072 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:54,163 - 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 1031ms') 2025-11-13 03:35:54,163 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:54,176 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:35:58,262 - 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 1023ms') 2025-11-13 03:35:58,262 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:35:58,287 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:36:02,353 - 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 1007ms') 2025-11-13 03:36:02,353 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:36:02,368 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:36:06,450 - 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-11-13 03:36:06,450 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:36:06,465 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:36:10,543 - 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 1011ms') 2025-11-13 03:36:10,543 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 failed! 2025-11-13 03:36:10,559 - DEBUG - Gateway for vn default-domain:ctest-TestSubInterfaces-40108125:ctest-vn-53386141 is 26.58.133.1 and allocation pool is NOT set 2025-11-13 03:36:12,623 - 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=13.7 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=5.02 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 5.017/9.365/13.713/4.348 ms') 2025-11-13 03:36:12,624 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-53445697 passed 2025-11-13 03:36:12,692 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:12,692 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-53445697, IP 26.58.133.3, Port 22 2025-11-13 03:36:12,758 - 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-11-13 03:36:12,860 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 is NOT ready for SSH connections, VM status: ACTIVE 2025-11-13 03:36:17,861 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:17,861 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-53445697, IP 26.58.133.3, Port 22 2025-11-13 03:36:17,929 - 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-11-13 03:36:18,004 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 is NOT ready for SSH connections, VM status: ACTIVE 2025-11-13 03:36:23,005 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:23,006 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-53445697, IP 26.58.133.3, Port 22 2025-11-13 03:36:23,074 - 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-11-13 03:36:23,158 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 is NOT ready for SSH connections, VM status: ACTIVE 2025-11-13 03:36:28,159 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:28,159 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-53445697, IP 26.58.133.3, Port 22 2025-11-13 03:36:28,225 - 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-11-13 03:36:28,306 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 is NOT ready for SSH connections, VM status: ACTIVE 2025-11-13 03:36:33,307 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:33,307 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-53445697, IP 26.58.133.3, Port 22 2025-11-13 03:36:33,473 - DEBUG - VM ctest-TestSubInterfaces-40108125-53445697 is ready for SSH connections 2025-11-13 03:36:33,474 - INFO - Waiting for VM ctest-TestSubInterfaces-40108125-31091680 to be up.. 2025-11-13 03:36:33,578 - DEBUG - VM is in ACTIVE state now 2025-11-13 03:36:33,579 - INFO - VM name : ctest-TestSubInterfaces-40108125-31091680 2025-11-13 03:36:33,661 - DEBUG - VM ctest-TestSubInterfaces-40108125-31091680 ID is c9a1f9d8-6e9a-4ba9-8563-c43fcfd90648 2025-11-13 03:36:33,661 - DEBUG - VM ctest-TestSubInterfaces-40108125-31091680 launched on Node an-jenkins-deploy-platform-ansible-os-4712-1 2025-11-13 03:36:33,760 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine/c9a1f9d8-6e9a-4ba9-8563-c43fcfd90648 2025-11-13 03:36:33,770 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine-interface/31001526-5baa-4d1f-82f3-de3611e4b1b7 2025-11-13 03:36:34,929 - 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=8.58 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=2.56 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 2.560/5.572/8.584/3.012 ms') 2025-11-13 03:36:34,929 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-TestSubInterfaces-40108125-31091680 passed 2025-11-13 03:36:34,996 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:34,996 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-31091680, IP 56.240.27.4, Port 22 2025-11-13 03:36:35,062 - 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-11-13 03:36:35,153 - DEBUG - VM ctest-TestSubInterfaces-40108125-31091680 is NOT ready for SSH connections, VM status: ACTIVE 2025-11-13 03:36:40,154 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:40,154 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-31091680, IP 56.240.27.4, Port 22 2025-11-13 03:36:40,325 - DEBUG - VM ctest-TestSubInterfaces-40108125-31091680 is ready for SSH connections 2025-11-13 03:36:40,326 - INFO - Waiting for VM ctest-TestSubInterfaces-40108125-65049929 to be up.. 2025-11-13 03:36:40,409 - DEBUG - VM is in ACTIVE state now 2025-11-13 03:36:40,409 - INFO - VM name : ctest-TestSubInterfaces-40108125-65049929 2025-11-13 03:36:40,497 - DEBUG - VM ctest-TestSubInterfaces-40108125-65049929 ID is 4307646f-471c-457d-8489-3fa6f38ee94b 2025-11-13 03:36:40,498 - DEBUG - VM ctest-TestSubInterfaces-40108125-65049929 launched on Node an-jenkins-deploy-platform-ansible-os-4712-2 2025-11-13 03:36:40,575 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine/4307646f-471c-457d-8489-3fa6f38ee94b 2025-11-13 03:36:40,587 - DEBUG - Requesting: http://10.0.0.61:8082/virtual-machine-interface/cbe3d5e7-5102-44f6-bb63-87e77eb874a1 2025-11-13 03:36:41,761 - DEBUG - (True, 'PING 169.254.0.5 (169.254.0.5) 56(84) bytes of data.\r\n64 bytes from 169.254.0.5: icmp_seq=1 ttl=63 time=4.38 ms\r\n64 bytes from 169.254.0.5: icmp_seq=2 ttl=63 time=3.29 ms\r\n\r\n--- 169.254.0.5 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 3.285/3.831/4.377/0.546 ms') 2025-11-13 03:36:41,762 - INFO - Ping to Metadata IP 169.254.0.5 of VM ctest-TestSubInterfaces-40108125-65049929 passed 2025-11-13 03:36:41,828 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:36:41,828 - DEBUG - Waiting to SSH to VM ctest-TestSubInterfaces-40108125-65049929, IP 26.58.133.5, Port 22 2025-11-13 03:36:41,987 - DEBUG - VM ctest-TestSubInterfaces-40108125-65049929 is ready for SSH connections 2025-11-13 03:36:41,987 - DEBUG - Running remote_cmd, Cmd : ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:36:41,988 - DEBUG - ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1 2025-11-13 03:36:56,934 - DEBUG - None 2025-11-13 03:37:01,934 - DEBUG - Running remote_cmd, Cmd : ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:01,935 - DEBUG - ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1 2025-11-13 03:37:02,909 - DEBUG - None 2025-11-13 03:37:07,910 - DEBUG - Running remote_cmd, Cmd : ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:07,910 - DEBUG - ifconfig -a| grep 90.49.145.67 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1 2025-11-13 03:37:09,303 - DEBUG - eth0.100 2025-11-13 03:37:09,303 - INFO - Interface eth0.100 is found on VM ebd5fc81-2926-4300-9b9a-1615de7e05f5 2025-11-13 03:37:09,303 - DEBUG - Running remote_cmd, Cmd : ifconfig -a| grep 56.240.27.3 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1, host_string: ubuntu@169.254.0.5, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:09,303 - DEBUG - ifconfig -a| grep 56.240.27.3 -A2 -B4| grep -i 'hwaddr\|flags' | awk '{print $1}' | cut -d ':' -f 1 2025-11-13 03:37:46,394 - DEBUG - eth0.100 2025-11-13 03:37:46,394 - INFO - Interface eth0.100 is found on VM 4307646f-471c-457d-8489-3fa6f38ee94b 2025-11-13 03:37:46,394 - DEBUG - Running remote_cmd, Cmd : route add -net 56.240.27.0/26 dev eth0.100, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:46,394 - DEBUG - route add -net 56.240.27.0/26 dev eth0.100 2025-11-13 03:37:46,912 - DEBUG - None 2025-11-13 03:37:46,912 - DEBUG - Running remote_cmd, Cmd : route add -net 90.49.145.64/26 dev eth0.100, host_string: ubuntu@169.254.0.5, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:46,912 - DEBUG - route add -net 90.49.145.64/26 dev eth0.100 2025-11-13 03:37:47,436 - DEBUG - None 2025-11-13 03:37:47,436 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-11-13 03:37:47,437 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 56.240.27.4, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:47,437 - DEBUG - ping -s 56 -c 3 -W 1 56.240.27.4 2025-11-13 03:37:49,978 - DEBUG - PING 56.240.27.4 (56.240.27.4) 56(84) bytes of data. 64 bytes from 56.240.27.4: icmp_req=1 ttl=63 time=7.95 ms 64 bytes from 56.240.27.4: icmp_req=2 ttl=63 time=1.46 ms 64 bytes from 56.240.27.4: icmp_req=3 ttl=63 time=1.62 ms --- 56.240.27.4 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2005ms rtt min/avg/max/mdev = 1.468/3.681/7.953/3.021 ms 2025-11-13 03:37:49,978 - INFO - Ping to IP 56.240.27.4 from VM ctest-TestSubInterfaces-40108125-53445697 passed 2025-11-13 03:37:49,978 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 56.240.27.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.23, gateway password: c0ntrail123 2025-11-13 03:37:49,979 - DEBUG - ping -s 56 -c 3 -W 1 56.240.27.3 2025-11-13 03:37:52,496 - DEBUG - PING 56.240.27.3 (56.240.27.3) 56(84) bytes of data. 64 bytes from 56.240.27.3: icmp_req=1 ttl=63 time=8.05 ms 64 bytes from 56.240.27.3: icmp_req=2 ttl=63 time=1.03 ms 64 bytes from 56.240.27.3: icmp_req=3 ttl=63 time=0.883 ms --- 56.240.27.3 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2004ms rtt min/avg/max/mdev = 0.883/3.323/8.055/3.346 ms 2025-11-13 03:37:52,496 - INFO - Ping to IP 56.240.27.3 from VM ctest-TestSubInterfaces-40108125-53445697 passed 2025-11-13 03:37:52,496 - INFO - Deleting interface with subnet_id 407297a8-d309-454e-aaf6-6a69d98e75f8, port_id None from router e06a1971-f3e3-47c3-a5ff-673f7f3dc784 2025-11-13 03:37:52,704 - INFO - Deleting interface with subnet_id 5c6c3c66-595c-4ac2-9c1e-b96a1a0e9029, port_id None from router e06a1971-f3e3-47c3-a5ff-673f7f3dc784 2025-11-13 03:37:53,029 - INFO - Detaching port cbe3d5e7-5102-44f6-bb63-87e77eb874a1 from VM ctest-TestSubInterfaces-40108125-65049929 2025-11-13 03:37:53,068 - INFO - Deleting VM ctest-TestSubInterfaces-40108125-65049929 2025-11-13 03:37:53,236 - INFO - Deleting VM ctest-TestSubInterfaces-40108125-31091680 2025-11-13 03:37:53,321 - INFO - Detaching port c55e5860-cfd9-402d-84e2-cb8a05fa5d0c from VM ctest-TestSubInterfaces-40108125-53445697 2025-11-13 03:37:53,354 - INFO - Deleting VM ctest-TestSubInterfaces-40108125-53445697 2025-11-13 03:37:54,743 - DEBUG - No XMPP flaps were noticed during the test
2025-11-13 03:37:54,743 - INFO - END TEST : test_vlan_interface_2 : PASSED[0:02:30]
2025-11-13 03:37:54,743 - INFO - -------------------------------------------------------------------------------- 2025-11-13 03:37:54,836 - INFO - Deleted port 5f23b6b4-a4d7-43f6-a35a-a9cded22a643 2025-11-13 03:37:55,031 - DEBUG - Response for delete_port : () 2025-11-13 03:37:55,031 - INFO - Deleted port cbe3d5e7-5102-44f6-bb63-87e77eb874a1 2025-11-13 03:37:55,143 - INFO - Deleted port 413afa3f-49a1-4119-bc6e-e9ef03b1826d 2025-11-13 03:37:55,305 - DEBUG - Response for delete_port : () 2025-11-13 03:37:55,305 - INFO - Deleted port 5b74fd60-96ef-430c-9125-0f2518abdc56 2025-11-13 03:37:55,388 - INFO - Deleted port e168248c-0b6b-4d10-a0c9-a7aa960e3b1a 2025-11-13 03:37:55,592 - DEBUG - Response for delete_port : () 2025-11-13 03:37:55,592 - INFO - Deleted port c55e5860-cfd9-402d-84e2-cb8a05fa5d0c 2025-11-13 03:37:55,593 - INFO - Deleting VN ctest-vn-87394230 2025-11-13 03:37:55,729 - DEBUG - Response for deleting network () 2025-11-13 03:37:55,729 - INFO - Deleting VN ctest-vn-53386141 2025-11-13 03:37:55,909 - DEBUG - Response for deleting network () 2025-11-13 03:37:55,910 - INFO - Deleting VN ctest-vn-30882035 2025-11-13 03:37:56,099 - DEBUG - Response for deleting network () 2025-11-13 03:37:56,796 - INFO - Deleted project: ctest-TestSubInterfaces-40108125, ID : 0c73bec4-e401-4afa-942f-02c1f22183be