2025-08-11 18:00:47,002 - INFO - Domain Default found not creating 2025-08-11 18:00:47,119 - INFO - Project ctest-TestBasicVMVN0-74142812 not found, creating it 2025-08-11 18:00:47,622 - INFO - Created Project:ctest-TestBasicVMVN0-74142812, ID : 95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:00:48,933 - INFO - ================================================================================ 2025-08-11 18:00:48,933 - INFO - STARTING TEST : test_control_node_switchover 2025-08-11 18:00:48,933 - INFO - TEST DESCRIPTION : Stop the control node and check peering with agent fallback to other control node. 1. Pick one VN from respource pool which has 2 VM's in it 2. Verify ping between VM's 3. Find active control node in cluster by agent inspect 4. Stop control service on active control node 5. Verify agents are connected to new active control-node using xmpp connections 6. Bring back control service on previous active node 7. Verify ping between VM's again after bringing up control serveice Pass criteria: Step 2,5 and 7 should pass 2025-08-11 18:00:50,194 - DEBUG - Skipping xmpp flap check 2025-08-11 18:00:50,194 - INFO - Initial checks done. Running the testcase now 2025-08-11 18:00:50,195 - INFO - 2025-08-11 18:00:50,866 - DEBUG - Response for create_network : {'network': {'id': '35d2a004-79a1-4d9b-a13c-191a53afd06e', 'name': 'ctest-vn1-34432976', 'tenant_id': '95f84723e25945f4a86e6c35c316e38f', 'project_id': '95f84723e25945f4a86e6c35c316e38f', 'admin_state_up': True, 'shared': False, 'status': 'ACTIVE', 'router:external': False, 'mtu': 0, 'subnets': [], 'fq_name': ['default-domain', 'ctest-TestBasicVMVN0-74142812', 'ctest-vn1-34432976'], 'port_security_enabled': True, 'description': ''}} 2025-08-11 18:00:51,099 - DEBUG - Response for create_subnet : {'subnet': {'id': '16b2098a-6c17-453d-a8bd-2e9454439f0e', 'name': '', 'tenant_id': '95f84723e25945f4a86e6c35c316e38f', 'network_id': '35d2a004-79a1-4d9b-a13c-191a53afd06e', 'ip_version': 4, 'cidr': '192.168.1.0/24', 'allocation_pools': [{'start': '192.168.1.2', 'end': '192.168.1.254'}], 'gateway_ip': '192.168.1.1', 'enable_dhcp': True, 'ipv6_ra_mode': None, 'ipv6_address_mode': None, 'dns_nameservers': [], 'host_routes': [], 'dns_server_address': '192.168.1.2', 'tags': [], 'project_id': '95f84723e25945f4a86e6c35c316e38f'}} 2025-08-11 18:00:51,127 - INFO - Created VN ctest-vn1-34432976 2025-08-11 18:00:51,139 - DEBUG - VN ctest-vn1-34432976 UUID is 35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,209 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:00:51,548 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:00:51,575 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:00:51,591 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:00:51,692 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,704 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,715 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:00:51,725 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:00:51,733 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/5e252cb8-4c8d-4aa8-a75c-b4a411dc2af3 2025-08-11 18:00:51,741 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:00:51,741 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,750 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:00:51,768 - INFO - Verified VN network id 12 for VN 35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,768 - INFO - Verifications in API Server for VN ctest-vn1-34432976 passed 2025-08-11 18:00:51,768 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,780 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:00:51,787 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:00:51,795 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/5e252cb8-4c8d-4aa8-a75c-b4a411dc2af3 2025-08-11 18:00:51,808 - DEBUG - Control-node 10.0.0.27 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '3878338170200346011', 'uuid-lslong': '11618188739572912238'}, 'enable': 'true', 'created': '2025-08-11T18:00:50', 'last-modified': '2025-08-11T18:00:51', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.761267'} 2025-08-11 18:00:51,814 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:00:51,820 - DEBUG - Control-node 10.0.0.23 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '3878338170200346011', 'uuid-lslong': '11618188739572912238'}, 'enable': 'true', 'created': '2025-08-11T18:00:50', 'last-modified': '2025-08-11T18:00:51', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.773835'} 2025-08-11 18:00:51,826 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:00:51,831 - DEBUG - Control-node 10.0.0.19 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '3878338170200346011', 'uuid-lslong': '11618188739572912238'}, 'enable': 'true', 'created': '2025-08-11T18:00:50', 'last-modified': '2025-08-11T18:00:51', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.786520'} 2025-08-11 18:00:51,838 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:00:51,838 - INFO - On all control nodes, Config, RI and RT verification for VN ctest-vn1-34432976 passed 2025-08-11 18:00:51,838 - DEBUG - ====Verifying policy data for ctest-vn1-34432976 in API_Server ====== 2025-08-11 18:00:51,838 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:00:51,844 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:00:51,855 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:00:51,938 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/35d2a004-79a1-4d9b-a13c-191a53afd06e 2025-08-11 18:00:51,948 - DEBUG - =>VN ctest-vn1-34432976 has no policy to be verified 2025-08-11 18:00:51,948 - DEBUG - Verifying the vn in opserver 2025-08-11 18:00:51,948 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 virtual network link through opserver 10.0.0.27 2025-08-11 18:00:51,948 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,241 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,298 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'href': 'http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat'} 2025-08-11 18:00:52,298 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 virtual network link through opserver 10.0.0.23 2025-08-11 18:00:52,298 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,589 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,640 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'href': 'http://10.0.0.23:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat'} 2025-08-11 18:00:52,640 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 virtual network link through opserver 10.0.0.19 2025-08-11 18:00:52,640 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,929 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-networks 2025-08-11 18:00:52,979 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'href': 'http://10.0.0.19:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat'} 2025-08-11 18:00:52,979 - INFO - Validated that VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is found in opserver 2025-08-11 18:00:53,002 - DEBUG - Do not have enough data to verify VN in agent 2025-08-11 18:00:53,012 - DEBUG - VRF ids for VN ctest-vn1-34432976: {} 2025-08-11 18:00:53,073 - DEBUG - Services list from nova: [, , , ] 2025-08-11 18:00:54,073 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3816-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3816-2) 2025-08-11 18:00:55,309 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3816-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3816-1) 2025-08-11 18:00:55,309 - INFO - Waiting for VM ctest-vn1_vm1-37309942 to be up.. 2025-08-11 18:00:55,396 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2025-08-11 18:01:00,478 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:01:00,478 - INFO - VM name : ctest-vn1_vm1-37309942 2025-08-11 18:01:00,549 - DEBUG - VM ctest-vn1_vm1-37309942 ID is 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:01:00,570 - DEBUG - VM ctest-vn1_vm1-37309942 launched on Node an-jenkins-deploy-platform-ansible-os-3816-2 2025-08-11 18:01:00,639 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:01:00,928 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:01:00,960 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/17ed23d1-9a71-44dc-b156-15169a1bd99e 2025-08-11 18:01:04,180 - 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-08-11 18:01:04,180 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:04,195 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:08,284 - 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 1028ms') 2025-08-11 18:01:08,284 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:08,299 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:12,375 - 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 1020ms') 2025-08-11 18:01:12,375 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:12,389 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:16,466 - 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-08-11 18:01:16,466 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:16,482 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:20,570 - 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-08-11 18:01:20,570 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:20,586 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:24,658 - 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-08-11 18:01:24,659 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:24,676 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:28,758 - 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-08-11 18:01:28,758 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 failed! 2025-08-11 18:01:28,772 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is 192.168.1.1 and allocation pool is NOT set 2025-08-11 18:01:30,839 - 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=4.68 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.08 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 = 1.076/2.878/4.681/1.802 ms') 2025-08-11 18:01:30,839 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-37309942 passed 2025-08-11 18:01:30,954 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:30,954 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-37309942, IP 192.168.1.3, Port 22 2025-08-11 18:01:31,020 - 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-08-11 18:01:31,089 - DEBUG - VM ctest-vn1_vm1-37309942 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:01:36,090 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:36,090 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-37309942, IP 192.168.1.3, Port 22 2025-08-11 18:01:36,146 - 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-08-11 18:01:36,215 - DEBUG - VM ctest-vn1_vm1-37309942 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:01:41,216 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:41,216 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-37309942, IP 192.168.1.3, Port 22 2025-08-11 18:01:41,284 - 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-08-11 18:01:41,352 - DEBUG - VM ctest-vn1_vm1-37309942 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:01:46,353 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:46,353 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-37309942, IP 192.168.1.3, Port 22 2025-08-11 18:01:46,420 - 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-08-11 18:01:46,501 - DEBUG - VM ctest-vn1_vm1-37309942 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:01:51,501 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:51,502 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-37309942, IP 192.168.1.3, Port 22 2025-08-11 18:01:51,669 - DEBUG - VM ctest-vn1_vm1-37309942 is ready for SSH connections 2025-08-11 18:01:51,669 - INFO - Waiting for VM ctest-vn1_vm2-51808094 to be up.. 2025-08-11 18:01:51,780 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:01:51,780 - INFO - VM name : ctest-vn1_vm2-51808094 2025-08-11 18:01:51,873 - DEBUG - VM ctest-vn1_vm2-51808094 ID is 822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:01:51,873 - DEBUG - VM ctest-vn1_vm2-51808094 launched on Node an-jenkins-deploy-platform-ansible-os-3816-1 2025-08-11 18:01:51,957 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:01:51,968 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 2025-08-11 18:01:53,171 - 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=6.45 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.42 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 = 1.421/3.935/6.449/2.514 ms') 2025-08-11 18:01:53,171 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm2-51808094 passed 2025-08-11 18:01:53,287 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:53,287 - DEBUG - Waiting to SSH to VM ctest-vn1_vm2-51808094, IP 192.168.1.4, Port 22 2025-08-11 18:01:53,453 - DEBUG - VM ctest-vn1_vm2-51808094 is ready for SSH connections 2025-08-11 18:01:53,453 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:01:53,453 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 192.168.1.4, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.249, gateway password: c0ntrail123 2025-08-11 18:01:53,453 - DEBUG - ping -s 56 -c 3 -W 1 192.168.1.4 2025-08-11 18:02:10,875 - DEBUG - PING 192.168.1.4 (192.168.1.4) 56(84) bytes of data. 64 bytes from 192.168.1.4: icmp_req=1 ttl=64 time=7.95 ms 64 bytes from 192.168.1.4: icmp_req=2 ttl=64 time=1.11 ms 64 bytes from 192.168.1.4: icmp_req=3 ttl=64 time=0.992 ms --- 192.168.1.4 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2004ms rtt min/avg/max/mdev = 0.992/3.354/7.956/3.254 ms 2025-08-11 18:02:10,875 - INFO - Ping to IP 192.168.1.4 from VM ctest-vn1_vm1-37309942 passed 2025-08-11 18:02:10,875 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:02:10,876 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 192.168.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.141, gateway password: c0ntrail123 2025-08-11 18:02:10,876 - DEBUG - ping -s 56 -c 3 -W 1 192.168.1.3 2025-08-11 18:02:47,000 - DEBUG - PING 192.168.1.3 (192.168.1.3) 56(84) bytes of data. 64 bytes from 192.168.1.3: icmp_req=1 ttl=64 time=6.54 ms 64 bytes from 192.168.1.3: icmp_req=2 ttl=64 time=0.949 ms 64 bytes from 192.168.1.3: icmp_req=3 ttl=64 time=0.888 ms --- 192.168.1.3 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2004ms rtt min/avg/max/mdev = 0.888/2.794/6.545/2.652 ms 2025-08-11 18:02:47,001 - INFO - Ping to IP 192.168.1.3 from VM ctest-vn1_vm2-51808094 passed 2025-08-11 18:02:47,007 - INFO - Active control node from the Agent 10.0.0.249 is 10.0.0.19 2025-08-11 18:02:47,007 - INFO - Stoping the Control service in 10.0.0.19 2025-08-11 18:02:47,410 - INFO - 10.0.0.19 2025-08-11 18:02:47,410 - INFO - control:inactive 2025-08-11 18:02:47,411 - INFO - Contrail services control are down on nodes 10.0.0.19 2025-08-11 18:02:52,418 - INFO - Active control node from the Agent 10.0.0.249 is 10.0.0.23 2025-08-11 18:02:52,418 - INFO - Starting the Control service in 10.0.0.19 2025-08-11 18:02:52,814 - INFO - 10.0.0.19 2025-08-11 18:02:52,818 - INFO - control:initializing 2025-08-11 18:02:52,818 - DEBUG - defaultdict(, {'10.0.0.19': {'control': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:02:52,819 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:02:57,916 - INFO - 10.0.0.19 2025-08-11 18:02:57,922 - INFO - control:active 2025-08-11 18:02:57,922 - INFO - Contrail services ['control'] are up on nodes 10.0.0.19 2025-08-11 18:03:03,011 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:03:03,012 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:03:03,012 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:03,019 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/17ed23d1-9a71-44dc-b156-15169a1bd99e 2025-08-11 18:03:03,029 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:03,036 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/17ed23d1-9a71-44dc-b156-15169a1bd99e 2025-08-11 18:03:03,046 - DEBUG - Requesting: http://10.0.0.19:8082/instance-ip/af3bc84c-c86a-485e-b22b-1e5f0d68a750 2025-08-11 18:03:03,054 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:03,054 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:03,061 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/17ed23d1-9a71-44dc-b156-15169a1bd99e 2025-08-11 18:03:03,070 - DEBUG - Requesting: http://10.0.0.19:8082/instance-ip/af3bc84c-c86a-485e-b22b-1e5f0d68a750 2025-08-11 18:03:03,078 - INFO - VM ctest-vn1_vm1-37309942 verfication in all API Servers passed 2025-08-11 18:03:03,096 - DEBUG - VM ctest-vn1_vm1-37309942 Tap interface: {'index': '3', 'name': 'tap17ed23d1-9a', 'uuid': '17ed23d1-9a71-44dc-b156-15169a1bd99e', 'vrf_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'active': 'Active', 'ipv4_active': 'Active', 'l2_active': 'L2 Active', 'ip6_active': 'Ipv6 Inactive < no-ipv6-addr >', 'health_check_active': 'Active', 'dhcp_service': 'Enable', 'dhcp_service_v6': 'Disable', 'dns_service': 'Enable', 'type': 'vport', 'label': '24', 'l2_label': '29', 'vxlan_id': '12', 'vn_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'vm_uuid': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'vm_name': 'ctest-vn1_vm1-37309942', 'ip_addr': '192.168.1.3', 'mac_addr': '02:17:ed:23:d1:9a', 'policy': 'Enable', 'fip_list': [], 'mdata_ip_addr': '169.254.0.3', 'service_vlan_list': None, 'os_ifindex': '161', 'fabric_port': 'NotFabricPort', 'alloc_linklocal_ip': 'LL-Enable', 'analyzer_name': None, 'config_name': 'default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e', 'sg_uuid_list': ['a55b0dbc-0c67-4890-9fd4-b15c0a777bd8'], 'static_route_list': None, 'vm_project_uuid': '95f84723-e259-45f4-a86e-6c35c316e38f', 'admin_state': 'Enabled', 'flow_key_idx': '23', 'allowed_address_pair_list': None, 'ip6_addr': '::', 'local_preference': '0', 'tx_vlan_id': '-1', 'rx_vlan_id': '-1', 'parent_interface': None, 'subnet': '--NA--', 'sub_type': 'Tap', 'vrf_assign_acl_uuid': '--NA--', 'vmi_type': 'Virtual Machine', 'transport': 'Ethernet', 'logical_interface_uuid': '00000000-0000-0000-0000-000000000000', 'flood_unknown_unicast': 'false', 'physical_device': None, 'physical_interface': None, 'fixed_ip4_list': None, 'fixed_ip6_list': None, 'fat_flow_list': None, 'metadata_ip_active': 'Active', 'service_health_check_ip': '0.0.0.0', 'alias_ip_list': None, 'drop_new_flows': 'false', 'bridge_domain_list': [], 'vmi_tag_list': None, 'policy_set_acl_list': None, 'slo_list': None, 'vhostuser_mode': '0', 'si_other_end_vmi': '00000000-0000-0000-0000-000000000000', 'cfg_igmp_enable': 'false', 'igmp_enabled': 'false', 'max_flows': '0', 'policy_set_fwaas_list': None, 'bond_interface_list': None, 'mac_ip_learning_enable': 'false', 'mac_ip_list': []} 2025-08-11 18:03:03,096 - DEBUG - Agent 10.0.0.249 vrf name: default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976 2025-08-11 18:03:03,101 - DEBUG - Agent VRF Object : {'vrf_list': [{'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'ucindex': '2', 'mcindex': '2', 'l2index': '2', 'source': 'Config; ', 'uc6index': '2', 'vn': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'table_label': '-1', 'vxlan_id': '12', 'evpnindex': '2', 'brindex': '2', 'mplsindex': '0', 'RD': '10.20.0.200:2', 'mac_aging_time': '0', 'layer2_control_word': 'false', 'forwarding_vrf': None, 'hbf_rintf': '-1', 'hbf_lintf': '-1'}]} 2025-08-11 18:03:03,220 - DEBUG - VM ctest-vn1_vm1-37309942 : Tap interface tap17ed23d1-9a is set to Active 2025-08-11 18:03:03,220 - DEBUG - Tap interface tap17ed23d1-9a detail : {'index': '3', 'name': 'tap17ed23d1-9a', 'uuid': '17ed23d1-9a71-44dc-b156-15169a1bd99e', 'vrf_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'active': 'Active', 'ipv4_active': 'Active', 'l2_active': 'L2 Active', 'ip6_active': 'Ipv6 Inactive < no-ipv6-addr >', 'health_check_active': 'Active', 'dhcp_service': 'Enable', 'dhcp_service_v6': 'Disable', 'dns_service': 'Enable', 'type': 'vport', 'label': '24', 'l2_label': '29', 'vxlan_id': '12', 'vn_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'vm_uuid': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'vm_name': 'ctest-vn1_vm1-37309942', 'ip_addr': '192.168.1.3', 'mac_addr': '02:17:ed:23:d1:9a', 'policy': 'Enable', 'fip_list': [], 'mdata_ip_addr': '169.254.0.3', 'service_vlan_list': None, 'os_ifindex': '161', 'fabric_port': 'NotFabricPort', 'alloc_linklocal_ip': 'LL-Enable', 'analyzer_name': None, 'config_name': 'default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e', 'sg_uuid_list': ['a55b0dbc-0c67-4890-9fd4-b15c0a777bd8'], 'static_route_list': None, 'vm_project_uuid': '95f84723-e259-45f4-a86e-6c35c316e38f', 'admin_state': 'Enabled', 'flow_key_idx': '23', 'allowed_address_pair_list': None, 'ip6_addr': '::', 'local_preference': '0', 'tx_vlan_id': '-1', 'rx_vlan_id': '-1', 'parent_interface': None, 'subnet': '--NA--', 'sub_type': 'Tap', 'vrf_assign_acl_uuid': '--NA--', 'vmi_type': 'Virtual Machine', 'transport': 'Ethernet', 'logical_interface_uuid': '00000000-0000-0000-0000-000000000000', 'flood_unknown_unicast': 'false', 'physical_device': None, 'physical_interface': None, 'fixed_ip4_list': None, 'fixed_ip6_list': None, 'fat_flow_list': None, 'metadata_ip_active': 'Active', 'service_health_check_ip': '0.0.0.0', 'alias_ip_list': None, 'drop_new_flows': 'false', 'bridge_domain_list': [], 'vmi_tag_list': None, 'policy_set_acl_list': None, 'slo_list': None, 'vhostuser_mode': '0', 'si_other_end_vmi': '00000000-0000-0000-0000-000000000000', 'cfg_igmp_enable': 'false', 'igmp_enabled': 'false', 'max_flows': '0', 'policy_set_fwaas_list': None, 'bond_interface_list': None, 'mac_ip_learning_enable': 'false', 'mac_ip_list': []} 2025-08-11 18:03:03,370 - DEBUG - Starting Layer 2 verification in Agent 2025-08-11 18:03:03,381 - DEBUG - Layer 2 path is seen for VM MAC 02:17:ed:23:d1:9a in agent 10.0.0.249 2025-08-11 18:03:03,381 - DEBUG - Active layer 2 route in agent is present for VMI tap17ed23d1-9a 2025-08-11 18:03:03,382 - DEBUG - L2 label(29) matches bw route table and interface table 2025-08-11 18:03:03,387 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is found in Agent of node 10.0.0.141 2025-08-11 18:03:03,553 - DEBUG - VRF IDs of VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is consistent in agent 10.0.0.141 2025-08-11 18:03:03,553 - DEBUG - Route for VM IP ['192.168.1.3'] is consistent in agent 10.0.0.141 2025-08-11 18:03:03,553 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 verification for VM ctest-vn1_vm1-37309942 in Agent 10.0.0.141 passed 2025-08-11 18:03:03,707 - DEBUG - Starting all layer 2 verification in agent 10.0.0.141 2025-08-11 18:03:03,718 - DEBUG - Route for VM MAC 02:17:ed:23:d1:9a is consistent in agent 10.0.0.141 2025-08-11 18:03:03,724 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is found in Agent of node 10.0.0.249 2025-08-11 18:03:03,893 - DEBUG - VRF IDs of VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is consistent in agent 10.0.0.249 2025-08-11 18:03:03,893 - DEBUG - Route for VM IP ['192.168.1.3'] is consistent in agent 10.0.0.249 2025-08-11 18:03:03,893 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 verification for VM ctest-vn1_vm1-37309942 in Agent 10.0.0.249 passed 2025-08-11 18:03:04,042 - DEBUG - Starting all layer 2 verification in agent 10.0.0.249 2025-08-11 18:03:04,053 - DEBUG - Route for VM MAC 02:17:ed:23:d1:9a is consistent in agent 10.0.0.249 2025-08-11 18:03:04,053 - INFO - VM ctest-vn1_vm1-37309942 verifications in Compute nodes passed 2025-08-11 18:03:04,320 - DEBUG - Validated VM route 192.168.1.3 in vrouter of 10.0.0.141 2025-08-11 18:03:04,323 - DEBUG - Remote Nh validation passed. Expected Tunnel, label: 10.20.0.200, 24; Got 10.20.0.200,24 2025-08-11 18:03:04,323 - DEBUG - Validated VM route 192.168.1.3 in vrouter of 10.0.0.141 2025-08-11 18:03:04,429 - DEBUG - Validated VM route 192.168.1.3 in vrouter of 10.0.0.249 2025-08-11 18:03:04,432 - DEBUG - Remote Nh validation passed. Expected Tunnel, label: None, 0; Got None,0 2025-08-11 18:03:04,432 - INFO - Validated routes of VM ctest-vn1_vm1-37309942 in all vrouters 2025-08-11 18:03:05,052 - DEBUG - Starting all layer2 verification in 10.0.0.23 Control Node 2025-08-11 18:03:05,222 - DEBUG - Layer2 route found for VM MAC 02:17:ed:23:d1:9a in Control-node 10.0.0.23 2025-08-11 18:03:05,222 - DEBUG - L2 Label for VM ctest-vn1_vm1-37309942 same between Control-node 10.0.0.23 and Agent, Expected: 29, Seen: 29 2025-08-11 18:03:05,222 - DEBUG - Starting all layer2 verification in 10.0.0.19 Control Node 2025-08-11 18:03:05,392 - DEBUG - Layer2 route found for VM MAC 02:17:ed:23:d1:9a in Control-node 10.0.0.19 2025-08-11 18:03:05,392 - DEBUG - L2 Label for VM ctest-vn1_vm1-37309942 same between Control-node 10.0.0.19 and Agent, Expected: 29, Seen: 29 2025-08-11 18:03:05,392 - INFO - Verification in Control-nodes for VM ctest-vn1_vm1-37309942 passed 2025-08-11 18:03:05,392 - DEBUG - Verifying the vm in opserver 2025-08-11 18:03:05,392 - DEBUG - Verifying in collector 10.0.0.19 ... 2025-08-11 18:03:05,392 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat 2025-08-11 18:03:05,410 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e?flat 2025-08-11 18:03:05,469 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e?flat 2025-08-11 18:03:05,489 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat 2025-08-11 18:03:05,542 - DEBUG - Verifying vm in vn uve 2025-08-11 18:03:05,542 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e?flat 2025-08-11 18:03:05,599 - DEBUG - VM uve shows interface as {'port_mirror_enabled': False, 'vn_uuid': '35d2a004-79a1-4d9b-a13c-191a53afd06e', 'label': 24, 'ip6_active': False, 'ip_address': '192.168.1.3', 'l2_active': True, 'ip4_active': True, 'rx_vlan': 65535, 'vm_uuid': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'active': True, 'vhostuser_mode': 0, 'fixed_ip4_list': ['192.168.1.3'], 'ip6_address': '::', 'virtual_network': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'gateway': '192.168.1.1', 'tx_vlan': 65535, 'uuid': '17ed23d1-9a71-44dc-b156-15169a1bd99e', 'mac_address': '02:17:ed:23:d1:9a', 'is_health_check_active': True, 'admin_state': True, '__T': 1754935368272843, 'vm_name': 'ctest-vn1_vm1-37309942'} 2025-08-11 18:03:05,599 - DEBUG - VM uve shows ip address as ['192.168.1.3', '::'] 2025-08-11 18:03:05,599 - DEBUG - VM uve shows virtual network as default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:05,599 - INFO - Verifying through opserver in 10.0.0.27 2025-08-11 18:03:05,600 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat 2025-08-11 18:03:05,631 - DEBUG - expected vm list 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:05,631 - DEBUG - Extracted vm list ['15165bc3-ecb0-4dd6-b4bc-5875fa65cb16'] 2025-08-11 18:03:05,631 - INFO - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is present in default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:05,631 - DEBUG - Verifying vm in vrouter uve 2025-08-11 18:03:05,631 - DEBUG - Getting info from collector 10.0.0.19.. 2025-08-11 18:03:05,631 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat 2025-08-11 18:03:05,684 - DEBUG - VM uve shows vrouter as ['an-jenkins-deploy-platform-ansible-os-3816-2'] 2025-08-11 18:03:05,684 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-2:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:05,742 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:03:05,778 - DEBUG - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:05,778 - DEBUG - Validated that VM ctest-vn1_vm1-37309942 is in Vrouter an-jenkins-deploy-platform-ansible-os-3816-2 UVE 2025-08-11 18:03:05,778 - DEBUG - Verifying vm tap interface/vn in vrouter uve 2025-08-11 18:03:05,786 - DEBUG - Expected tap interface of VM uuid 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e 2025-08-11 18:03:05,787 - DEBUG - Expected VN of VM uuid 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:05,787 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-2:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:05,842 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:03:05,878 - DEBUG - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:05,878 - INFO - tap interface default-domain:ctest-TestBasicVMVN0-74142812:17ed23d1-9a71-44dc-b156-15169a1bd99e of vm 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:05,879 - DEBUG - Connected network default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 of vm 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:05,879 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.27 2025-08-11 18:03:05,879 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machines 2025-08-11 18:03:05,889 - DEBUG - VM link and name as {'name': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'href': 'http://10.0.0.27:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat'} 2025-08-11 18:03:05,889 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.23 2025-08-11 18:03:05,890 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-machines 2025-08-11 18:03:05,939 - DEBUG - VM link and name as {'name': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'href': 'http://10.0.0.23:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat'} 2025-08-11 18:03:05,939 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.19 2025-08-11 18:03:05,939 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machines 2025-08-11 18:03:05,951 - DEBUG - VM link and name as {'name': '15165bc3-ecb0-4dd6-b4bc-5875fa65cb16', 'href': 'http://10.0.0.19:8081/analytics/uves/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16?flat'} 2025-08-11 18:03:05,951 - INFO - VM ctest-vn1_vm1-37309942 validations in Opserver passed 2025-08-11 18:03:06,017 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:03:06,017 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:03:06,017 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:06,025 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 2025-08-11 18:03:06,035 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:06,041 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 2025-08-11 18:03:06,050 - DEBUG - Requesting: http://10.0.0.19:8082/instance-ip/fcf15a33-daa6-47cd-a93c-9c8f160ed36a 2025-08-11 18:03:06,059 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:06,059 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:06,065 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 2025-08-11 18:03:06,074 - DEBUG - Requesting: http://10.0.0.19:8082/instance-ip/fcf15a33-daa6-47cd-a93c-9c8f160ed36a 2025-08-11 18:03:06,081 - INFO - VM ctest-vn1_vm2-51808094 verfication in all API Servers passed 2025-08-11 18:03:06,098 - DEBUG - VM ctest-vn1_vm2-51808094 Tap interface: {'index': '3', 'name': 'tap2acb02f2-c6', 'uuid': '2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0', 'vrf_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'active': 'Active', 'ipv4_active': 'Active', 'l2_active': 'L2 Active', 'ip6_active': 'Ipv6 Inactive < no-ipv6-addr >', 'health_check_active': 'Active', 'dhcp_service': 'Enable', 'dhcp_service_v6': 'Disable', 'dns_service': 'Enable', 'type': 'vport', 'label': '25', 'l2_label': '29', 'vxlan_id': '12', 'vn_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'vm_uuid': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'vm_name': 'ctest-vn1_vm2-51808094', 'ip_addr': '192.168.1.4', 'mac_addr': '02:2a:cb:02:f2:c6', 'policy': 'Enable', 'fip_list': [], 'mdata_ip_addr': '169.254.0.3', 'service_vlan_list': None, 'os_ifindex': '127', 'fabric_port': 'NotFabricPort', 'alloc_linklocal_ip': 'LL-Enable', 'analyzer_name': None, 'config_name': 'default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0', 'sg_uuid_list': ['a55b0dbc-0c67-4890-9fd4-b15c0a777bd8'], 'static_route_list': None, 'vm_project_uuid': '95f84723-e259-45f4-a86e-6c35c316e38f', 'admin_state': 'Enabled', 'flow_key_idx': '28', 'allowed_address_pair_list': None, 'ip6_addr': '::', 'local_preference': '0', 'tx_vlan_id': '-1', 'rx_vlan_id': '-1', 'parent_interface': None, 'subnet': '--NA--', 'sub_type': 'Tap', 'vrf_assign_acl_uuid': '--NA--', 'vmi_type': 'Virtual Machine', 'transport': 'Ethernet', 'logical_interface_uuid': '00000000-0000-0000-0000-000000000000', 'flood_unknown_unicast': 'false', 'physical_device': None, 'physical_interface': None, 'fixed_ip4_list': None, 'fixed_ip6_list': None, 'fat_flow_list': None, 'metadata_ip_active': 'Active', 'service_health_check_ip': '0.0.0.0', 'alias_ip_list': None, 'drop_new_flows': 'false', 'bridge_domain_list': [], 'vmi_tag_list': None, 'policy_set_acl_list': None, 'slo_list': None, 'vhostuser_mode': '0', 'si_other_end_vmi': '00000000-0000-0000-0000-000000000000', 'cfg_igmp_enable': 'false', 'igmp_enabled': 'false', 'max_flows': '0', 'policy_set_fwaas_list': None, 'bond_interface_list': None, 'mac_ip_learning_enable': 'false', 'mac_ip_list': []} 2025-08-11 18:03:06,098 - DEBUG - Agent 10.0.0.141 vrf name: default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976 2025-08-11 18:03:06,103 - DEBUG - Agent VRF Object : {'vrf_list': [{'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'ucindex': '2', 'mcindex': '2', 'l2index': '2', 'source': 'Config; ', 'uc6index': '2', 'vn': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'table_label': '-1', 'vxlan_id': '12', 'evpnindex': '2', 'brindex': '2', 'mplsindex': '0', 'RD': '10.20.0.201:2', 'mac_aging_time': '0', 'layer2_control_word': 'false', 'forwarding_vrf': None, 'hbf_rintf': '-1', 'hbf_lintf': '-1'}]} 2025-08-11 18:03:06,232 - DEBUG - VM ctest-vn1_vm2-51808094 : Tap interface tap2acb02f2-c6 is set to Active 2025-08-11 18:03:06,232 - DEBUG - Tap interface tap2acb02f2-c6 detail : {'index': '3', 'name': 'tap2acb02f2-c6', 'uuid': '2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0', 'vrf_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976:ctest-vn1-34432976', 'active': 'Active', 'ipv4_active': 'Active', 'l2_active': 'L2 Active', 'ip6_active': 'Ipv6 Inactive < no-ipv6-addr >', 'health_check_active': 'Active', 'dhcp_service': 'Enable', 'dhcp_service_v6': 'Disable', 'dns_service': 'Enable', 'type': 'vport', 'label': '25', 'l2_label': '29', 'vxlan_id': '12', 'vn_name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'vm_uuid': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'vm_name': 'ctest-vn1_vm2-51808094', 'ip_addr': '192.168.1.4', 'mac_addr': '02:2a:cb:02:f2:c6', 'policy': 'Enable', 'fip_list': [], 'mdata_ip_addr': '169.254.0.3', 'service_vlan_list': None, 'os_ifindex': '127', 'fabric_port': 'NotFabricPort', 'alloc_linklocal_ip': 'LL-Enable', 'analyzer_name': None, 'config_name': 'default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0', 'sg_uuid_list': ['a55b0dbc-0c67-4890-9fd4-b15c0a777bd8'], 'static_route_list': None, 'vm_project_uuid': '95f84723-e259-45f4-a86e-6c35c316e38f', 'admin_state': 'Enabled', 'flow_key_idx': '28', 'allowed_address_pair_list': None, 'ip6_addr': '::', 'local_preference': '0', 'tx_vlan_id': '-1', 'rx_vlan_id': '-1', 'parent_interface': None, 'subnet': '--NA--', 'sub_type': 'Tap', 'vrf_assign_acl_uuid': '--NA--', 'vmi_type': 'Virtual Machine', 'transport': 'Ethernet', 'logical_interface_uuid': '00000000-0000-0000-0000-000000000000', 'flood_unknown_unicast': 'false', 'physical_device': None, 'physical_interface': None, 'fixed_ip4_list': None, 'fixed_ip6_list': None, 'fat_flow_list': None, 'metadata_ip_active': 'Active', 'service_health_check_ip': '0.0.0.0', 'alias_ip_list': None, 'drop_new_flows': 'false', 'bridge_domain_list': [], 'vmi_tag_list': None, 'policy_set_acl_list': None, 'slo_list': None, 'vhostuser_mode': '0', 'si_other_end_vmi': '00000000-0000-0000-0000-000000000000', 'cfg_igmp_enable': 'false', 'igmp_enabled': 'false', 'max_flows': '0', 'policy_set_fwaas_list': None, 'bond_interface_list': None, 'mac_ip_learning_enable': 'false', 'mac_ip_list': []} 2025-08-11 18:03:06,383 - DEBUG - Starting Layer 2 verification in Agent 2025-08-11 18:03:06,395 - DEBUG - Layer 2 path is seen for VM MAC 02:2a:cb:02:f2:c6 in agent 10.0.0.141 2025-08-11 18:03:06,395 - DEBUG - Active layer 2 route in agent is present for VMI tap2acb02f2-c6 2025-08-11 18:03:06,395 - DEBUG - L2 label(29) matches bw route table and interface table 2025-08-11 18:03:06,401 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is found in Agent of node 10.0.0.141 2025-08-11 18:03:06,573 - DEBUG - VRF IDs of VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is consistent in agent 10.0.0.141 2025-08-11 18:03:06,573 - DEBUG - Route for VM IP ['192.168.1.4'] is consistent in agent 10.0.0.141 2025-08-11 18:03:06,573 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 verification for VM ctest-vn1_vm2-51808094 in Agent 10.0.0.141 passed 2025-08-11 18:03:06,726 - DEBUG - Starting all layer 2 verification in agent 10.0.0.141 2025-08-11 18:03:06,737 - DEBUG - Route for VM MAC 02:2a:cb:02:f2:c6 is consistent in agent 10.0.0.141 2025-08-11 18:03:06,743 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is found in Agent of node 10.0.0.249 2025-08-11 18:03:06,912 - DEBUG - VRF IDs of VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 is consistent in agent 10.0.0.249 2025-08-11 18:03:06,912 - DEBUG - Route for VM IP ['192.168.1.4'] is consistent in agent 10.0.0.249 2025-08-11 18:03:06,912 - DEBUG - VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 verification for VM ctest-vn1_vm2-51808094 in Agent 10.0.0.249 passed 2025-08-11 18:03:07,062 - DEBUG - Starting all layer 2 verification in agent 10.0.0.249 2025-08-11 18:03:07,073 - DEBUG - Route for VM MAC 02:2a:cb:02:f2:c6 is consistent in agent 10.0.0.249 2025-08-11 18:03:07,073 - INFO - VM ctest-vn1_vm2-51808094 verifications in Compute nodes passed 2025-08-11 18:03:07,338 - DEBUG - Validated VM route 192.168.1.4 in vrouter of 10.0.0.141 2025-08-11 18:03:07,341 - DEBUG - Remote Nh validation passed. Expected Tunnel, label: None, 0; Got None,0 2025-08-11 18:03:07,445 - DEBUG - Validated VM route 192.168.1.4 in vrouter of 10.0.0.249 2025-08-11 18:03:07,448 - DEBUG - Remote Nh validation passed. Expected Tunnel, label: 10.20.0.201, 25; Got 10.20.0.201,25 2025-08-11 18:03:07,448 - DEBUG - Validated VM route 192.168.1.4 in vrouter of 10.0.0.249 2025-08-11 18:03:07,448 - INFO - Validated routes of VM ctest-vn1_vm2-51808094 in all vrouters 2025-08-11 18:03:08,016 - DEBUG - Starting all layer2 verification in 10.0.0.23 Control Node 2025-08-11 18:03:08,182 - DEBUG - Layer2 route found for VM MAC 02:2a:cb:02:f2:c6 in Control-node 10.0.0.23 2025-08-11 18:03:08,182 - DEBUG - L2 Label for VM ctest-vn1_vm2-51808094 same between Control-node 10.0.0.23 and Agent, Expected: 29, Seen: 29 2025-08-11 18:03:08,182 - DEBUG - Starting all layer2 verification in 10.0.0.19 Control Node 2025-08-11 18:03:08,352 - DEBUG - Layer2 route found for VM MAC 02:2a:cb:02:f2:c6 in Control-node 10.0.0.19 2025-08-11 18:03:08,352 - DEBUG - L2 Label for VM ctest-vn1_vm2-51808094 same between Control-node 10.0.0.19 and Agent, Expected: 29, Seen: 29 2025-08-11 18:03:08,352 - INFO - Verification in Control-nodes for VM ctest-vn1_vm2-51808094 passed 2025-08-11 18:03:08,352 - DEBUG - Verifying the vm in opserver 2025-08-11 18:03:08,352 - DEBUG - Verifying in collector 10.0.0.19 ... 2025-08-11 18:03:08,352 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat 2025-08-11 18:03:08,367 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0?flat 2025-08-11 18:03:08,390 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0?flat 2025-08-11 18:03:08,409 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat 2025-08-11 18:03:08,424 - DEBUG - Verifying vm in vn uve 2025-08-11 18:03:08,424 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machine-interface/default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0?flat 2025-08-11 18:03:08,442 - DEBUG - VM uve shows interface as {'tx_vlan': 65535, 'ip6_address': '::', 'gateway': '192.168.1.1', 'l2_active': True, 'vhostuser_mode': 0, 'ip4_active': True, 'uuid': '2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0', 'label': 25, 'mac_address': '02:2a:cb:02:f2:c6', 'fixed_ip4_list': ['192.168.1.4'], 'port_mirror_enabled': False, 'ip_address': '192.168.1.4', 'vn_uuid': '35d2a004-79a1-4d9b-a13c-191a53afd06e', '__T': 1754935269766902, 'vm_uuid': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'is_health_check_active': True, 'virtual_network': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976', 'active': True, 'vm_name': 'ctest-vn1_vm2-51808094', 'rx_vlan': 65535, 'admin_state': True, 'ip6_active': False} 2025-08-11 18:03:08,442 - DEBUG - VM uve shows ip address as ['192.168.1.4', '::'] 2025-08-11 18:03:08,442 - DEBUG - VM uve shows virtual network as default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:08,442 - INFO - Verifying through opserver in 10.0.0.27 2025-08-11 18:03:08,442 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat 2025-08-11 18:03:08,480 - DEBUG - expected vm list 822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:08,480 - DEBUG - Extracted vm list ['822c2700-fa79-4a77-82c3-fdc439c9ed7f'] 2025-08-11 18:03:08,480 - INFO - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is present in default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:08,480 - DEBUG - Verifying vm in vrouter uve 2025-08-11 18:03:08,480 - DEBUG - Getting info from collector 10.0.0.19.. 2025-08-11 18:03:08,480 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat 2025-08-11 18:03:08,496 - DEBUG - VM uve shows vrouter as ['an-jenkins-deploy-platform-ansible-os-3816-1'] 2025-08-11 18:03:08,496 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:08,540 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:08,575 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:08,575 - DEBUG - Validated that VM ctest-vn1_vm2-51808094 is in Vrouter an-jenkins-deploy-platform-ansible-os-3816-1 UVE 2025-08-11 18:03:08,575 - DEBUG - Verifying vm tap interface/vn in vrouter uve 2025-08-11 18:03:08,582 - DEBUG - Expected tap interface of VM uuid 822c2700-fa79-4a77-82c3-fdc439c9ed7f is default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 2025-08-11 18:03:08,582 - DEBUG - Expected VN of VM uuid 822c2700-fa79-4a77-82c3-fdc439c9ed7f is default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:08,582 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:08,621 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:08,656 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:08,657 - INFO - tap interface default-domain:ctest-TestBasicVMVN0-74142812:2acb02f2-c6d9-4eeb-ba9a-f80e3a80e5d0 of vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:08,657 - DEBUG - Connected network default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 of vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f is present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:08,657 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.27 2025-08-11 18:03:08,657 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machines 2025-08-11 18:03:08,667 - DEBUG - VM link and name as {'name': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'href': 'http://10.0.0.27:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat'} 2025-08-11 18:03:08,667 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.23 2025-08-11 18:03:08,668 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-machines 2025-08-11 18:03:08,679 - DEBUG - VM link and name as {'name': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'href': 'http://10.0.0.23:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat'} 2025-08-11 18:03:08,679 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.19 2025-08-11 18:03:08,679 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machines 2025-08-11 18:03:08,689 - DEBUG - VM link and name as {'name': '822c2700-fa79-4a77-82c3-fdc439c9ed7f', 'href': 'http://10.0.0.19:8081/analytics/uves/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f?flat'} 2025-08-11 18:03:08,689 - INFO - VM ctest-vn1_vm2-51808094 validations in Opserver passed 2025-08-11 18:03:08,689 - INFO - Checking the ping between the VM again 2025-08-11 18:03:08,689 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:03:08,689 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 192.168.1.4, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.249, gateway password: c0ntrail123 2025-08-11 18:03:08,689 - DEBUG - ping -s 56 -c 3 -W 1 192.168.1.4 2025-08-11 18:03:11,120 - DEBUG - PING 192.168.1.4 (192.168.1.4) 56(84) bytes of data. 64 bytes from 192.168.1.4: icmp_req=1 ttl=64 time=3.90 ms 64 bytes from 192.168.1.4: icmp_req=2 ttl=64 time=0.925 ms 64 bytes from 192.168.1.4: icmp_req=3 ttl=64 time=0.983 ms --- 192.168.1.4 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2004ms rtt min/avg/max/mdev = 0.925/1.936/3.900/1.388 ms 2025-08-11 18:03:11,120 - INFO - Ping to IP 192.168.1.4 from VM ctest-vn1_vm1-37309942 passed 2025-08-11 18:03:11,120 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:03:11,120 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 192.168.1.3, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.141, gateway password: c0ntrail123 2025-08-11 18:03:11,120 - DEBUG - ping -s 56 -c 3 -W 1 192.168.1.3 2025-08-11 18:03:13,544 - DEBUG - PING 192.168.1.3 (192.168.1.3) 56(84) bytes of data. 64 bytes from 192.168.1.3: icmp_req=1 ttl=64 time=2.20 ms 64 bytes from 192.168.1.3: icmp_req=2 ttl=64 time=0.815 ms 64 bytes from 192.168.1.3: icmp_req=3 ttl=64 time=0.885 ms --- 192.168.1.3 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2003ms rtt min/avg/max/mdev = 0.815/1.300/2.200/0.637 ms 2025-08-11 18:03:13,544 - INFO - Ping to IP 192.168.1.3 from VM ctest-vn1_vm2-51808094 passed 2025-08-11 18:03:13,544 - INFO - Deleting VM ctest-vn1_vm2-51808094 2025-08-11 18:03:13,606 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:13,607 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:13,616 - DEBUG - VM ID 822c2700-fa79-4a77-82c3-fdc439c9ed7f of VM ctest-vn1_vm2-51808094 is still found in API Server 2025-08-11 18:03:15,617 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:15,617 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:15,633 - DEBUG - Response Code: 404 2025-08-11 18:03:15,633 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:15,641 - DEBUG - Response Code: 404 2025-08-11 18:03:15,642 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/822c2700-fa79-4a77-82c3-fdc439c9ed7f 2025-08-11 18:03:15,648 - DEBUG - Response Code: 404 2025-08-11 18:03:15,648 - INFO - VM ctest-vn1_vm2-51808094 is fully removed in API-Server 2025-08-11 18:03:15,805 - DEBUG - Skipping VM-deletion-check in nova db since mysql_token is not found 2025-08-11 18:03:15,840 - DEBUG - Validated that vrouter 10.0.0.141 does not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:15,952 - DEBUG - VM route 192.168.1.4 has been marked for discard in VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 of compute 10.0.0.249 2025-08-11 18:03:15,954 - DEBUG - Validated that vrouter 10.0.0.249 does not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:15,954 - INFO - Validated that all vrouters do not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:15,954 - INFO - VM ctest-vn1_vm2-51808094 is removed in Compute, and routes are removed in all compute nodes 2025-08-11 18:03:16,252 - INFO - Routes for VM ctest-vn1_vm2-51808094 is removed in all control-nodes 2025-08-11 18:03:16,253 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:16,292 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:16,334 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:16,334 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:16,334 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:16,334 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:19,335 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:19,377 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:19,413 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:19,413 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:19,413 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:19,413 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:22,414 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:22,452 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:22,486 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:22,486 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:22,486 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:22,486 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:25,487 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:25,526 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:25,561 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:25,561 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:25,561 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:25,561 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:28,562 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:28,602 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:28,637 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:28,637 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:28,637 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:28,637 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:31,639 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:31,704 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:31,749 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:31,749 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:31,749 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:31,749 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:34,750 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:34,790 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:34,825 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:34,825 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:34,825 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:34,825 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:37,826 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:37,865 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:37,900 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:37,900 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:37,900 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:37,900 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:40,901 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-1:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:40,939 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:03:40,974 - DEBUG - VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is not present in vrouter an-jenkins-deploy-platform-ansible-os-3816-1 uve 2025-08-11 18:03:40,974 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:40,974 - DEBUG - interface for vm 822c2700-fa79-4a77-82c3-fdc439c9ed7f deleted from vrouter uve ... 2025-08-11 18:03:40,974 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:40,974 - DEBUG - Validated that VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is removed in Vrouter UVE 2025-08-11 18:03:40,974 - DEBUG - Verifying through opserver in 10.0.0.27 2025-08-11 18:03:40,974 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat 2025-08-11 18:03:41,000 - DEBUG - 822c2700-fa79-4a77-82c3-fdc439c9ed7f BM not in default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 uve 2025-08-11 18:03:41,000 - DEBUG - Validated that VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is not present in the VN UVE 2025-08-11 18:03:41,000 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.27 2025-08-11 18:03:41,000 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machines 2025-08-11 18:03:41,010 - INFO - 822c2700-fa79-4a77-82c3-fdc439c9ed7f vm uve deleted from opserver 2025-08-11 18:03:41,010 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.23 2025-08-11 18:03:41,010 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-machines 2025-08-11 18:03:41,059 - INFO - 822c2700-fa79-4a77-82c3-fdc439c9ed7f vm uve deleted from opserver 2025-08-11 18:03:41,059 - DEBUG - Verifying the 822c2700-fa79-4a77-82c3-fdc439c9ed7f virtual network link through opserver 10.0.0.19 2025-08-11 18:03:41,059 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machines 2025-08-11 18:03:41,071 - INFO - 822c2700-fa79-4a77-82c3-fdc439c9ed7f vm uve deleted from opserver 2025-08-11 18:03:41,071 - INFO - Validated that VM 822c2700-fa79-4a77-82c3-fdc439c9ed7f is removed from Opserver 2025-08-11 18:03:41,071 - INFO - Deleting VM ctest-vn1_vm1-37309942 2025-08-11 18:03:41,129 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:41,129 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:41,137 - DEBUG - VM ID 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 of VM ctest-vn1_vm1-37309942 is still found in API Server 2025-08-11 18:03:43,138 - DEBUG - Verifying in api server 10.0.0.19 2025-08-11 18:03:43,138 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:43,147 - DEBUG - Response Code: 404 2025-08-11 18:03:43,147 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:43,152 - DEBUG - Response Code: 404 2025-08-11 18:03:43,152 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 2025-08-11 18:03:43,157 - DEBUG - Response Code: 404 2025-08-11 18:03:43,157 - INFO - VM ctest-vn1_vm1-37309942 is fully removed in API-Server 2025-08-11 18:03:43,310 - DEBUG - Skipping VM-deletion-check in nova db since mysql_token is not found 2025-08-11 18:03:43,352 - DEBUG - Validated that vrouter 10.0.0.141 does not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:43,362 - DEBUG - Validated that vrouter 10.0.0.249 does not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:43,362 - INFO - Validated that all vrouters do not have VMs route for VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 2025-08-11 18:03:43,362 - INFO - VM ctest-vn1_vm1-37309942 is removed in Compute, and routes are removed in all compute nodes 2025-08-11 18:03:43,633 - INFO - Routes for VM ctest-vn1_vm1-37309942 is removed in all control-nodes 2025-08-11 18:03:43,633 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-2:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:43,690 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:03:43,725 - DEBUG - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:43,726 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:43,726 - DEBUG - interface for vm 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 deleted from vrouter uve ... 2025-08-11 18:03:43,726 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:46,726 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-2:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:46,784 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:03:46,834 - DEBUG - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is still present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:46,834 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:46,834 - DEBUG - interface for vm 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 deleted from vrouter uve ... 2025-08-11 18:03:46,835 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:49,835 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/generator/an-jenkins-deploy-platform-ansible-os-3816-2:Compute:contrail-vrouter-agent:0?flat 2025-08-11 18:03:49,891 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:03:49,928 - DEBUG - VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is not present in vrouter an-jenkins-deploy-platform-ansible-os-3816-2 uve 2025-08-11 18:03:49,928 - DEBUG - Verifying if the vm interface deleted from vroter uve... 2025-08-11 18:03:49,928 - DEBUG - interface for vm 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 deleted from vrouter uve ... 2025-08-11 18:03:49,928 - DEBUG - Deleted interface not in error interface list ... 2025-08-11 18:03:49,928 - DEBUG - Validated that VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is removed in Vrouter UVE 2025-08-11 18:03:49,928 - DEBUG - Verifying through opserver in 10.0.0.27 2025-08-11 18:03:49,929 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976?flat 2025-08-11 18:03:49,946 - DEBUG - 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 BM not in default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-34432976 uve 2025-08-11 18:03:49,946 - DEBUG - Validated that VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is not present in the VN UVE 2025-08-11 18:03:49,947 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.27 2025-08-11 18:03:49,947 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-machines 2025-08-11 18:03:49,957 - INFO - 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 vm uve deleted from opserver 2025-08-11 18:03:49,957 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.23 2025-08-11 18:03:49,957 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-machines 2025-08-11 18:03:49,968 - INFO - 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 vm uve deleted from opserver 2025-08-11 18:03:49,969 - DEBUG - Verifying the 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 virtual network link through opserver 10.0.0.19 2025-08-11 18:03:49,969 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-machines 2025-08-11 18:03:49,981 - INFO - 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 vm uve deleted from opserver 2025-08-11 18:03:49,981 - INFO - Validated that VM 15165bc3-ecb0-4dd6-b4bc-5875fa65cb16 is removed from Opserver 2025-08-11 18:03:49,981 - INFO - Deleting VN ctest-vn1-34432976 2025-08-11 18:03:50,150 - DEBUG - Response for deleting network () 2025-08-11 18:03:50,150 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/969899c4-a3bc-4e5b-b5ba-9b61ee5caeb6 2025-08-11 18:03:50,156 - DEBUG - Response Code: 404 2025-08-11 18:03:50,156 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:03:50,161 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:03:50,213 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:03:50,300 - INFO - Validated that VN ctest-vn1-34432976 is not found in API Server 2025-08-11 18:03:50,312 - DEBUG - VN ctest-vn1-34432976 is not present in Agent 10.0.0.141 2025-08-11 18:03:50,322 - DEBUG - VN ctest-vn1-34432976 is not present in Agent 10.0.0.249 2025-08-11 18:03:50,322 - INFO - Validated that VN ctest-vn1-34432976 is not in any agent 2025-08-11 18:03:50,352 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn1-34432976 info 2025-08-11 18:03:51,602 - DEBUG - Skipping xmpp flap check
2025-08-11 18:03:51,602 - INFO - END TEST : test_control_node_switchover : PASSED[0:03:03]
2025-08-11 18:03:51,602 - INFO - -------------------------------------------------------------------------------- 2025-08-11 18:03:51,605 - INFO - ================================================================================ 2025-08-11 18:03:51,605 - INFO - STARTING TEST : test_process_restart_in_policy_between_vns 2025-08-11 18:03:51,605 - INFO - TEST DESCRIPTION : Test to validate that with policy having rule to check icmp fwding between VMs on different VNs , ping between VMs should pass with process restarts 1. Pick 2 VN's from resource pool which has one VM each 2. Create policy with icmp allow rule between those VN's and bind it networks 3. Ping from one VM to another VM 4. Restart process 'vrouter' and 'control' on setup 5. Ping again between VM's after process restart Pass criteria: Step 2,3,4 and 5 should pass 2025-08-11 18:03:52,850 - DEBUG - Skipping xmpp flap check 2025-08-11 18:03:52,850 - INFO - Initial checks done. Running the testcase now 2025-08-11 18:03:52,850 - INFO - 2025-08-11 18:03:52,857 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = icmp, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345, security_group = None, network_policy = None, subnet_list = []], src_ports = [start_port = -1, end_port = -1], application = [], dst_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053, security_group = None, network_policy = None, subnet_list = []], dst_ports = [start_port = -1, end_port = -1], action_list = simple_action = pass, gateway_name = None, apply_service = [], service_properties = None, mirror_to = None, assign_routing_instance = None, log = False, alert = False, qos_action = None, host_based_service = False, ethertype = None, created = None, last_modified = None, description = None] 2025-08-11 18:03:53,158 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = icmp, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053, security_group = None, network_policy = None, subnet_list = []], src_ports = [start_port = -1, end_port = -1], application = [], dst_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345, security_group = None, network_policy = None, subnet_list = []], dst_ports = [start_port = -1, end_port = -1], action_list = simple_action = pass, gateway_name = None, apply_service = [], service_properties = None, mirror_to = None, assign_routing_instance = None, log = False, alert = False, qos_action = None, host_based_service = False, ethertype = None, created = None, last_modified = None, description = None] 2025-08-11 18:03:53,678 - INFO - Created VN ctest-vn1-08808345, UUID :90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:53,989 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:03:53,995 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:03:54,005 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:03:54,102 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,114 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,124 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:03:54,131 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:03:54,140 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/289ee0f5-b7ad-40e0-b6ec-a40445bb7a40 2025-08-11 18:03:54,146 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:03:54,146 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,155 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:03:54,170 - INFO - Verified VN network id 12 for VN 90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,170 - INFO - Verifications in API Server for VN ctest-vn1-08808345 passed 2025-08-11 18:03:54,170 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,179 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:03:54,186 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:03:54,193 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/289ee0f5-b7ad-40e0-b6ec-a40445bb7a40 2025-08-11 18:03:54,209 - DEBUG - Control-node 10.0.0.27 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '10440348911866234479', 'uuid-lslong': '9226640931566198560'}, 'enable': 'true', 'created': '2025-08-11T18:03:53', 'last-modified': '2025-08-11T18:03:53', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.377583'} 2025-08-11 18:03:54,215 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:03:54,221 - DEBUG - Control-node 10.0.0.23 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '10440348911866234479', 'uuid-lslong': '9226640931566198560'}, 'enable': 'true', 'created': '2025-08-11T18:03:53', 'last-modified': '2025-08-11T18:03:53', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.388872'} 2025-08-11 18:03:54,227 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:03:54,233 - DEBUG - Control-node 10.0.0.19 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '10440348911866234479', 'uuid-lslong': '9226640931566198560'}, 'enable': 'true', 'created': '2025-08-11T18:03:53', 'last-modified': '2025-08-11T18:03:53', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.407607'} 2025-08-11 18:03:54,240 - DEBUG - Route Targets: ['target:64512:8000005'] 2025-08-11 18:03:54,240 - INFO - On all control nodes, Config, RI and RT verification for VN ctest-vn1-08808345 passed 2025-08-11 18:03:54,240 - DEBUG - ====Verifying policy data for ctest-vn1-08808345 in API_Server ====== 2025-08-11 18:03:54,240 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:03:54,247 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:03:54,259 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:03:54,346 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/90e39205-1eec-466f-800b-9d0adc151f20 2025-08-11 18:03:54,356 - DEBUG - =>VN ctest-vn1-08808345 has no policy to be verified 2025-08-11 18:03:54,356 - DEBUG - Verifying the vn in opserver 2025-08-11 18:03:54,356 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 virtual network link through opserver 10.0.0.27 2025-08-11 18:03:54,356 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-networks 2025-08-11 18:03:54,366 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'href': 'http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345?flat'} 2025-08-11 18:03:54,366 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 virtual network link through opserver 10.0.0.23 2025-08-11 18:03:54,366 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-networks 2025-08-11 18:03:54,377 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'href': 'http://10.0.0.23:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345?flat'} 2025-08-11 18:03:54,377 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 virtual network link through opserver 10.0.0.19 2025-08-11 18:03:54,377 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-networks 2025-08-11 18:03:54,388 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345', 'href': 'http://10.0.0.19:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345?flat'} 2025-08-11 18:03:54,388 - INFO - Validated that VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is found in opserver 2025-08-11 18:03:54,408 - DEBUG - Do not have enough data to verify VN in agent 2025-08-11 18:03:54,417 - DEBUG - VRF ids for VN ctest-vn1-08808345: {} 2025-08-11 18:03:55,039 - INFO - Created VN ctest-vn2-19813053, UUID :589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,366 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:03:55,371 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:03:55,382 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:03:55,466 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,478 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,486 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:03:55,494 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:03:55,500 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/7286ece6-a535-4752-8201-ccb29c694595 2025-08-11 18:03:55,506 - DEBUG - Route Targets: ['target:64512:8000006'] 2025-08-11 18:03:55,506 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,514 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:03:55,528 - INFO - Verified VN network id 13 for VN 589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,529 - INFO - Verifications in API Server for VN ctest-vn2-19813053 passed 2025-08-11 18:03:55,529 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,537 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:03:55,543 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:03:55,549 - DEBUG - Requesting: http://10.0.0.27:8082/route-target/7286ece6-a535-4752-8201-ccb29c694595 2025-08-11 18:03:55,560 - DEBUG - Control-node 10.0.0.27 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '6385408853650851996', 'uuid-lslong': '10315719713302777094'}, 'enable': 'true', 'created': '2025-08-11T18:03:54', 'last-modified': '2025-08-11T18:03:55', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.361883'} 2025-08-11 18:03:55,566 - DEBUG - Route Targets: ['target:64512:8000006'] 2025-08-11 18:03:55,571 - DEBUG - Control-node 10.0.0.23 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '6385408853650851996', 'uuid-lslong': '10315719713302777094'}, 'enable': 'true', 'created': '2025-08-11T18:03:54', 'last-modified': '2025-08-11T18:03:55', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.374119'} 2025-08-11 18:03:55,577 - DEBUG - Route Targets: ['target:64512:8000006'] 2025-08-11 18:03:55,584 - DEBUG - Control-node 10.0.0.19 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-74142812', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '6385408853650851996', 'uuid-lslong': '10315719713302777094'}, 'enable': 'true', 'created': '2025-08-11T18:03:54', 'last-modified': '2025-08-11T18:03:55', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.368999'} 2025-08-11 18:03:55,590 - DEBUG - Route Targets: ['target:64512:8000006'] 2025-08-11 18:03:55,590 - INFO - On all control nodes, Config, RI and RT verification for VN ctest-vn2-19813053 passed 2025-08-11 18:03:55,590 - DEBUG - ====Verifying policy data for ctest-vn2-19813053 in API_Server ====== 2025-08-11 18:03:55,590 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:03:55,596 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:03:55,607 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:03:55,696 - DEBUG - Requesting: http://10.0.0.27:8082/virtual-network/589d8785-637e-489c-8f28-cc6c99e80d06 2025-08-11 18:03:55,706 - DEBUG - =>VN ctest-vn2-19813053 has no policy to be verified 2025-08-11 18:03:55,706 - DEBUG - Verifying the vn in opserver 2025-08-11 18:03:55,707 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053 virtual network link through opserver 10.0.0.27 2025-08-11 18:03:55,707 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/virtual-networks 2025-08-11 18:03:55,718 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'href': 'http://10.0.0.27:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053?flat'} 2025-08-11 18:03:55,718 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053 virtual network link through opserver 10.0.0.23 2025-08-11 18:03:55,718 - DEBUG - Requesting: http://10.0.0.23:8081/analytics/uves/virtual-networks 2025-08-11 18:03:55,729 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'href': 'http://10.0.0.23:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053?flat'} 2025-08-11 18:03:55,729 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053 virtual network link through opserver 10.0.0.19 2025-08-11 18:03:55,730 - DEBUG - Requesting: http://10.0.0.19:8081/analytics/uves/virtual-networks 2025-08-11 18:03:55,741 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053', 'href': 'http://10.0.0.19:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053?flat'} 2025-08-11 18:03:55,741 - INFO - Validated that VN default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn2-19813053 is found in opserver 2025-08-11 18:03:55,764 - DEBUG - Do not have enough data to verify VN in agent 2025-08-11 18:03:55,774 - DEBUG - VRF ids for VN ctest-vn2-19813053: {} 2025-08-11 18:03:57,141 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3816-2), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3816-2) 2025-08-11 18:03:58,337 - INFO - VM ([]) created on node: (an-jenkins-deploy-platform-ansible-os-3816-1), Zone: (nova:an-jenkins-deploy-platform-ansible-os-3816-1) 2025-08-11 18:03:58,337 - INFO - Waiting for VM ctest-vn1_vm1-08399036 to be up.. 2025-08-11 18:03:58,422 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2025-08-11 18:04:03,504 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:04:03,504 - INFO - VM name : ctest-vn1_vm1-08399036 2025-08-11 18:04:03,571 - DEBUG - VM ctest-vn1_vm1-08399036 ID is 10089491-cdfb-416b-8d5b-1bdd7bfc96ac 2025-08-11 18:04:03,571 - DEBUG - VM ctest-vn1_vm1-08399036 launched on Node an-jenkins-deploy-platform-ansible-os-3816-2 2025-08-11 18:04:03,639 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/10089491-cdfb-416b-8d5b-1bdd7bfc96ac 2025-08-11 18:04:03,649 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/7ccec62b-d09d-4d05-9405-aa32a59f39c9 2025-08-11 18:04:06,869 - 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 1032ms') 2025-08-11 18:04:06,869 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:06,882 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:10,973 - 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-08-11 18:04:10,973 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:10,986 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:15,058 - 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-08-11 18:04:15,058 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:15,072 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:19,157 - 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-08-11 18:04:19,157 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:19,171 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:23,257 - 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 1020ms') 2025-08-11 18:04:23,257 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:23,271 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:27,349 - 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') 2025-08-11 18:04:27,349 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:27,363 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:31,448 - 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') 2025-08-11 18:04:31,448 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 failed! 2025-08-11 18:04:31,463 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-74142812:ctest-vn1-08808345 is 192.168.1.254 and allocation pool is NOT set 2025-08-11 18:04:33,527 - 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=6.13 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=1.94 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 = 1.939/4.033/6.127/2.094 ms') 2025-08-11 18:04:33,527 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-08399036 passed 2025-08-11 18:04:33,644 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:33,644 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-08399036, IP 192.168.1.252, Port 22 2025-08-11 18:04:33,712 - 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-08-11 18:04:33,784 - DEBUG - VM ctest-vn1_vm1-08399036 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:04:38,785 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:38,785 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-08399036, IP 192.168.1.252, Port 22 2025-08-11 18:04:38,842 - 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-08-11 18:04:38,913 - DEBUG - VM ctest-vn1_vm1-08399036 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:04:43,913 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:43,913 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-08399036, IP 192.168.1.252, Port 22 2025-08-11 18:04:43,971 - 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-08-11 18:04:44,049 - DEBUG - VM ctest-vn1_vm1-08399036 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:04:49,051 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:49,051 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-08399036, IP 192.168.1.252, Port 22 2025-08-11 18:04:49,106 - 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-08-11 18:04:49,184 - DEBUG - VM ctest-vn1_vm1-08399036 is NOT ready for SSH connections, VM status: ACTIVE 2025-08-11 18:04:54,184 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:54,184 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-08399036, IP 192.168.1.252, Port 22 2025-08-11 18:04:54,352 - DEBUG - VM ctest-vn1_vm1-08399036 is ready for SSH connections 2025-08-11 18:04:54,352 - INFO - Waiting for VM ctest-vn2_vm1-90085937 to be up.. 2025-08-11 18:04:54,429 - DEBUG - VM is in ACTIVE state now 2025-08-11 18:04:54,429 - INFO - VM name : ctest-vn2_vm1-90085937 2025-08-11 18:04:54,527 - DEBUG - VM ctest-vn2_vm1-90085937 ID is 17572daf-a563-496d-81cc-296728b8df3c 2025-08-11 18:04:54,527 - DEBUG - VM ctest-vn2_vm1-90085937 launched on Node an-jenkins-deploy-platform-ansible-os-3816-1 2025-08-11 18:04:54,602 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine/17572daf-a563-496d-81cc-296728b8df3c 2025-08-11 18:04:54,613 - DEBUG - Requesting: http://10.0.0.19:8082/virtual-machine-interface/4c468388-190b-424c-896e-ee1670e81f03 2025-08-11 18:04:55,821 - 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=3.19 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=4.00 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 = 3.186/3.590/3.995/0.404 ms') 2025-08-11 18:04:55,821 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn2_vm1-90085937 passed 2025-08-11 18:04:55,932 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:55,932 - DEBUG - Waiting to SSH to VM ctest-vn2_vm1-90085937, IP 192.168.2.252, Port 22 2025-08-11 18:04:56,086 - DEBUG - VM ctest-vn2_vm1-90085937 is ready for SSH connections 2025-08-11 18:04:56,086 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-08-11 18:04:56,087 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 3 -W 1 192.168.2.252, host_string: ubuntu@169.254.0.3, password: ubuntugateway: ubuntu@10.0.0.249, gateway password: c0ntrail123 2025-08-11 18:04:56,087 - DEBUG - ping -s 56 -c 3 -W 1 192.168.2.252 2025-08-11 18:05:15,370 - DEBUG - PING 192.168.2.252 (192.168.2.252) 56(84) bytes of data. 64 bytes from 192.168.2.252: icmp_req=1 ttl=63 time=7.03 ms 64 bytes from 192.168.2.252: icmp_req=2 ttl=63 time=1.08 ms 64 bytes from 192.168.2.252: icmp_req=3 ttl=63 time=0.901 ms --- 192.168.2.252 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2004ms rtt min/avg/max/mdev = 0.901/3.007/7.036/2.849 ms 2025-08-11 18:05:15,371 - INFO - Ping to IP 192.168.2.252 from VM ctest-vn1_vm1-08399036 passed 2025-08-11 18:05:18,722 - INFO - 10.0.0.141 2025-08-11 18:05:18,727 - INFO - agent:initializing 2025-08-11 18:05:18,727 - DEBUG - defaultdict(, {'10.0.0.141': {'agent': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:18,727 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:23,814 - INFO - 10.0.0.141 2025-08-11 18:05:23,820 - INFO - agent:active 2025-08-11 18:05:23,821 - INFO - Contrail services ['agent'] are up on nodes 10.0.0.141 2025-08-11 18:05:27,212 - INFO - 10.0.0.249 2025-08-11 18:05:27,216 - INFO - agent:initializing 2025-08-11 18:05:27,216 - DEBUG - defaultdict(, {'10.0.0.249': {'agent': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:27,216 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:32,310 - INFO - 10.0.0.249 2025-08-11 18:05:32,316 - INFO - agent:active 2025-08-11 18:05:32,316 - INFO - Contrail services ['agent'] are up on nodes 10.0.0.249 2025-08-11 18:05:32,824 - INFO - 10.0.0.27 2025-08-11 18:05:32,828 - INFO - control:initializing 2025-08-11 18:05:32,828 - DEBUG - defaultdict(, {'10.0.0.27': {'control': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:32,828 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:37,931 - INFO - 10.0.0.27 2025-08-11 18:05:37,937 - INFO - control:active 2025-08-11 18:05:37,937 - INFO - Contrail services ['control'] are up on nodes 10.0.0.27 2025-08-11 18:05:38,336 - INFO - 10.0.0.23 2025-08-11 18:05:38,340 - INFO - control:initializing 2025-08-11 18:05:38,340 - DEBUG - defaultdict(, {'10.0.0.23': {'control': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:38,340 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:43,437 - INFO - 10.0.0.23 2025-08-11 18:05:43,449 - INFO - control:active 2025-08-11 18:05:43,450 - INFO - Contrail services ['control'] are up on nodes 10.0.0.23 2025-08-11 18:05:43,899 - INFO - 10.0.0.19 2025-08-11 18:05:43,904 - INFO - control:initializing 2025-08-11 18:05:43,904 - DEBUG - defaultdict(, {'10.0.0.19': {'control': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:43,904 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:49,005 - INFO - 10.0.0.19 2025-08-11 18:05:49,011 - INFO - control:active 2025-08-11 18:05:49,011 - INFO - Contrail services ['control'] are up on nodes 10.0.0.19 2025-08-11 18:05:49,712 - INFO - 10.0.0.27 2025-08-11 18:05:49,716 - INFO - api-server:initializing 2025-08-11 18:05:49,716 - DEBUG - defaultdict(, {'10.0.0.27': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:49,716 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:05:54,826 - INFO - 10.0.0.27 2025-08-11 18:05:54,830 - INFO - api-server:initializing 2025-08-11 18:05:54,830 - DEBUG - defaultdict(, {'10.0.0.27': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:05:54,830 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 1 2025-08-11 18:05:59,931 - INFO - 10.0.0.27 2025-08-11 18:05:59,939 - INFO - api-server:initializing (Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down) 2025-08-11 18:05:59,939 - DEBUG - defaultdict(, {'10.0.0.27': {'api-server': {'status': 'initializing', 'description': 'Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down'}}}) 2025-08-11 18:05:59,939 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 2 2025-08-11 18:06:05,054 - INFO - 10.0.0.27 2025-08-11 18:06:05,060 - INFO - api-server:active 2025-08-11 18:06:05,060 - INFO - Contrail services ['api-server'] are up on nodes 10.0.0.27 2025-08-11 18:06:05,636 - INFO - 10.0.0.23 2025-08-11 18:06:05,642 - INFO - api-server:initializing 2025-08-11 18:06:05,642 - DEBUG - defaultdict(, {'10.0.0.23': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:06:05,643 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:06:10,733 - INFO - 10.0.0.23 2025-08-11 18:06:10,737 - INFO - api-server:initializing 2025-08-11 18:06:10,738 - DEBUG - defaultdict(, {'10.0.0.23': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:06:10,738 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 1 2025-08-11 18:06:15,849 - INFO - 10.0.0.23 2025-08-11 18:06:15,854 - INFO - api-server:initializing (Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down) 2025-08-11 18:06:15,855 - DEBUG - defaultdict(, {'10.0.0.23': {'api-server': {'status': 'initializing', 'description': 'Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down'}}}) 2025-08-11 18:06:15,855 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 2 2025-08-11 18:06:20,966 - INFO - 10.0.0.23 2025-08-11 18:06:20,971 - INFO - api-server:active 2025-08-11 18:06:20,971 - INFO - Contrail services ['api-server'] are up on nodes 10.0.0.23 2025-08-11 18:06:21,622 - INFO - 10.0.0.19 2025-08-11 18:06:21,627 - INFO - api-server:initializing 2025-08-11 18:06:21,628 - DEBUG - defaultdict(, {'10.0.0.19': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:06:21,628 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-08-11 18:06:26,734 - INFO - 10.0.0.19 2025-08-11 18:06:26,739 - INFO - api-server:initializing 2025-08-11 18:06:26,739 - DEBUG - defaultdict(, {'10.0.0.19': {'api-server': {'status': 'initializing', 'description': None}}}) 2025-08-11 18:06:26,739 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 1 2025-08-11 18:06:31,840 - INFO - 10.0.0.19 2025-08-11 18:06:31,846 - INFO - api-server:initializing (Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down) 2025-08-11 18:06:31,846 - DEBUG - defaultdict(, {'10.0.0.19': {'api-server': {'status': 'initializing', 'description': 'Collector:Collector[none to Idle on EvStart], Generic Connection:Keystone[] connection down'}}}) 2025-08-11 18:06:31,846 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 2 2025-08-11 18:06:36,944 - INFO - 10.0.0.19 2025-08-11 18:06:36,950 - INFO - api-server:active 2025-08-11 18:06:36,950 - INFO - Contrail services ['api-server'] are up on nodes 10.0.0.19 2025-08-11 18:06:37,054 - INFO - 10.0.0.27 2025-08-11 18:06:37,055 - INFO - config 2025-08-11 18:06:37,063 - INFO - config-nodemgr:active 2025-08-11 18:06:37,071 - INFO - api-server:active 2025-08-11 18:06:37,075 - INFO - schema:backup 2025-08-11 18:06:37,080 - INFO - svc-monitor:active 2025-08-11 18:06:37,084 - INFO - device-manager:backup 2025-08-11 18:06:37,084 - INFO - config-database 2025-08-11 18:06:37,084 - INFO - config-cassandra:active 2025-08-11 18:06:37,084 - INFO - config-zookeeper:active 2025-08-11 18:06:37,084 - INFO - config-rabbitmq:active 2025-08-11 18:06:37,084 - INFO - control 2025-08-11 18:06:37,090 - INFO - control-nodemgr:active 2025-08-11 18:06:37,095 - INFO - control:active 2025-08-11 18:06:37,096 - INFO - named:active 2025-08-11 18:06:37,106 - INFO - dns:active 2025-08-11 18:06:37,106 - INFO - analytics 2025-08-11 18:06:37,114 - INFO - analytics-nodemgr:active 2025-08-11 18:06:37,119 - INFO - analytics-api:active 2025-08-11 18:06:37,126 - INFO - collector:active 2025-08-11 18:06:37,126 - INFO - analytics-database 2025-08-11 18:06:37,126 - INFO - analytics-cassandra:active 2025-08-11 18:06:37,134 - INFO - analyticsdb-nodemgr:active 2025-08-11 18:06:37,143 - INFO - query-engine:active 2025-08-11 18:06:37,143 - INFO - webui 2025-08-11 18:06:37,144 - INFO - webui:active 2025-08-11 18:06:37,144 - INFO - webui-middleware:active 2025-08-11 18:06:37,144 - INFO - redis:active 2025-08-11 18:06:37,144 - INFO - analytics_snmp 2025-08-11 18:06:37,150 - INFO - snmp-collector:active 2025-08-11 18:06:37,150 - INFO - snmp-topology:active 2025-08-11 18:06:37,150 - INFO - analytics_alarm 2025-08-11 18:06:37,150 - INFO - alarmgen:active 2025-08-11 18:06:37,238 - INFO - 10.0.0.23 2025-08-11 18:06:37,238 - INFO - config 2025-08-11 18:06:37,245 - INFO - config-nodemgr:active 2025-08-11 18:06:37,251 - INFO - api-server:active 2025-08-11 18:06:37,257 - INFO - schema:active 2025-08-11 18:06:37,266 - INFO - svc-monitor:backup 2025-08-11 18:06:37,272 - INFO - device-manager:active 2025-08-11 18:06:37,273 - INFO - config-database 2025-08-11 18:06:37,273 - INFO - config-cassandra:active 2025-08-11 18:06:37,273 - INFO - config-zookeeper:active 2025-08-11 18:06:37,273 - INFO - config-rabbitmq:active 2025-08-11 18:06:37,274 - INFO - control 2025-08-11 18:06:37,279 - INFO - control-nodemgr:active 2025-08-11 18:06:37,286 - INFO - control:active 2025-08-11 18:06:37,286 - INFO - named:active 2025-08-11 18:06:37,293 - INFO - dns:active 2025-08-11 18:06:37,293 - INFO - analytics 2025-08-11 18:06:37,299 - INFO - analytics-nodemgr:active 2025-08-11 18:06:37,303 - INFO - analytics-api:active 2025-08-11 18:06:37,308 - INFO - collector:active 2025-08-11 18:06:37,308 - INFO - analytics-database 2025-08-11 18:06:37,308 - INFO - analytics-cassandra:active 2025-08-11 18:06:37,314 - INFO - analyticsdb-nodemgr:active 2025-08-11 18:06:37,320 - INFO - query-engine:active 2025-08-11 18:06:37,321 - INFO - webui 2025-08-11 18:06:37,321 - INFO - webui:active 2025-08-11 18:06:37,321 - INFO - webui-middleware:active 2025-08-11 18:06:37,321 - INFO - redis:active 2025-08-11 18:06:37,321 - INFO - analytics_snmp 2025-08-11 18:06:37,325 - INFO - snmp-collector:active 2025-08-11 18:06:37,325 - INFO - snmp-topology:active 2025-08-11 18:06:37,325 - INFO - analytics_alarm 2025-08-11 18:06:37,325 - INFO - alarmgen:active 2025-08-11 18:06:37,427 - INFO - 10.0.0.19 2025-08-11 18:06:37,428 - INFO - config 2025-08-11 18:06:37,434 - INFO - config-nodemgr:active 2025-08-11 18:06:37,439 - INFO - api-server:active 2025-08-11 18:06:37,444 - INFO - schema:backup 2025-08-11 18:06:37,449 - INFO - svc-monitor:backup 2025-08-11 18:06:37,453 - INFO - device-manager:backup 2025-08-11 18:06:37,454 - INFO - config-database 2025-08-11 18:06:37,454 - INFO - config-cassandra:active 2025-08-11 18:06:37,454 - INFO - config-zookeeper:active 2025-08-11 18:06:37,454 - INFO - config-rabbitmq:active 2025-08-11 18:06:37,454 - INFO - control 2025-08-11 18:06:37,460 - INFO - control-nodemgr:active 2025-08-11 18:06:37,467 - INFO - control:active 2025-08-11 18:06:37,467 - INFO - named:active 2025-08-11 18:06:37,474 - INFO - dns:active 2025-08-11 18:06:37,474 - INFO - analytics 2025-08-11 18:06:37,480 - INFO - analytics-nodemgr:active 2025-08-11 18:06:37,485 - INFO - analytics-api:active 2025-08-11 18:06:37,491 - INFO - collector:active 2025-08-11 18:06:37,491 - INFO - analytics-database 2025-08-11 18:06:37,491 - INFO - analytics-cassandra:active 2025-08-11 18:06:37,496 - INFO - analyticsdb-nodemgr:active 2025-08-11 18:06:37,503 - INFO - query-engine:active 2025-08-11 18:06:37,503 - INFO - webui 2025-08-11 18:06:37,503 - INFO - webui:active 2025-08-11 18:06:37,503 - INFO - webui-middleware:active 2025-08-11 18:06:37,503 - INFO - redis:active 2025-08-11 18:06:37,503 - INFO - analytics_snmp 2025-08-11 18:06:37,508 - INFO - snmp-collector:active 2025-08-11 18:06:37,508 - INFO - snmp-topology:active 2025-08-11 18:06:37,508 - INFO - analytics_alarm 2025-08-11 18:06:37,508 - INFO - alarmgen:active 2025-08-11 18:06:37,598 - INFO - 10.0.0.141 2025-08-11 18:06:37,598 - INFO - vrouter 2025-08-11 18:06:37,604 - INFO - vrouter-nodemgr:active 2025-08-11 18:06:37,610 - INFO - agent:active 2025-08-11 18:06:37,698 - INFO - 10.0.0.249 2025-08-11 18:06:37,698 - INFO - vrouter 2025-08-11 18:06:37,703 - INFO - vrouter-nodemgr:active 2025-08-11 18:06:37,709 - INFO - agent:active 2025-08-11 18:06:37,709 - INFO - All the contrail services are up on all nodes 2025-08-11 18:06:37,709 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/vrouter/an-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:06:37,786 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.193:5269'] servers UP 2025-08-11 18:06:37,786 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1 connected to xmpp 10.20.0.193 2025-08-11 18:06:37,786 - WARNING - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.129:5269'] servers NOT UP 2025-08-11 18:06:37,786 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.192:5269'] servers UP 2025-08-11 18:06:37,786 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1 connected to xmpp 10.20.0.192 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.193:53'] servers UP 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1 connected to dns 10.20.0.193 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.129:53'] servers UP 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1 connected to dns 10.20.0.129 2025-08-11 18:06:37,787 - WARNING - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.20.0.192:53'] servers NOT UP 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.0.0.27:8086'] servers UP 2025-08-11 18:06:37,787 - INFO - an-jenkins-deploy-platform-ansible-os-3816-1 connected to collector 10.0.0.27 2025-08-11 18:06:37,787 - WARNING - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.0.0.23:8086'] servers NOT UP 2025-08-11 18:06:37,787 - WARNING - an-jenkins-deploy-platform-ansible-os-3816-1:contrail-vrouter-agent module connection to ['10.0.0.19:8086'] servers NOT UP 2025-08-11 18:06:37,787 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/control-node/cn-jenkins-deploy-platform-ansible-os-3816-1?flat 2025-08-11 18:06:37,856 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-1:contrail-control module connection to 10.0.0.27:9041 servers UP 2025-08-11 18:06:37,856 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-1:contrail-control module connection to 10.0.0.27:5673 servers UP 2025-08-11 18:06:37,857 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-1:contrail-control module connection to ['10.0.0.27:8086'] servers UP 2025-08-11 18:06:37,857 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/control-node/cn-jenkins-deploy-platform-ansible-os-3816-2?flat 2025-08-11 18:06:37,916 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-2:contrail-control module connection to 10.0.0.27:9041 servers UP 2025-08-11 18:06:37,916 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-2:contrail-control module connection to 10.0.0.27:5673 servers UP 2025-08-11 18:06:37,916 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-2:contrail-control module connection to ['10.0.0.27:8086'] servers UP 2025-08-11 18:06:37,916 - DEBUG - Requesting: http://10.0.0.27:8081/analytics/uves/control-node/cn-jenkins-deploy-platform-ansible-os-3816-3?flat 2025-08-11 18:06:37,937 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-3:contrail-control module connection to 10.0.0.27:9041 servers UP 2025-08-11 18:06:37,937 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-3:contrail-control module connection to 10.0.0.27:5673 servers UP 2025-08-11 18:06:37,937 - INFO - cn-jenkins-deploy-platform-ansible-os-3816-3:contrail-control module connection to ['10.0.0.27:8086'] servers UP 2025-08-11 18:06:37,947 - INFO - Deleting VM ctest-vn2_vm1-90085937 2025-08-11 18:06:38,034 - INFO - Deleting VM ctest-vn1_vm1-08399036 2025-08-11 18:06:38,321 - INFO - Deleting VN ctest-vn2-19813053 2025-08-11 18:06:38,374 - DEBUG - RefsExistError Delete when resource still referred: ['http://10.0.0.19:8082/virtual-machine-interface/4c468388-190b-424c-896e-ee1670e81f03'] while deleting VN ctest-vn2-19813053..Will retry 2025-08-11 18:06:40,544 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/87832f2d-03f9-4416-9351-d0fa8eeefc52 2025-08-11 18:06:40,576 - DEBUG - Response Code: 404 2025-08-11 18:06:40,576 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:06:40,588 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:06:40,611 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:06:40,704 - INFO - Validated that VN ctest-vn2-19813053 is not found in API Server 2025-08-11 18:06:40,717 - DEBUG - VN ctest-vn2-19813053 is not present in Agent 10.0.0.141 2025-08-11 18:06:40,729 - DEBUG - VN ctest-vn2-19813053 is not present in Agent 10.0.0.249 2025-08-11 18:06:40,729 - INFO - Validated that VN ctest-vn2-19813053 is not in any agent 2025-08-11 18:06:40,765 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn2-19813053 info 2025-08-11 18:06:40,934 - INFO - Deleting VN ctest-vn1-08808345 2025-08-11 18:06:41,049 - DEBUG - Requesting: http://10.0.0.27:8082/routing-instance/1e786ae6-80b7-4d07-a433-9d2a2d0d5aed 2025-08-11 18:06:41,055 - DEBUG - Response Code: 404 2025-08-11 18:06:41,055 - DEBUG - Requesting: http://10.0.0.27:8082/domains 2025-08-11 18:06:41,064 - DEBUG - Requesting: http://10.0.0.27:8082/domain/4bc87c47-8b22-47dc-8747-cffafaf5f39a 2025-08-11 18:06:41,081 - DEBUG - Requesting: http://10.0.0.27:8082/project/95f84723-e259-45f4-a86e-6c35c316e38f 2025-08-11 18:06:41,178 - INFO - Validated that VN ctest-vn1-08808345 is not found in API Server 2025-08-11 18:06:41,191 - DEBUG - VN ctest-vn1-08808345 is not present in Agent 10.0.0.141 2025-08-11 18:06:41,202 - DEBUG - VN ctest-vn1-08808345 is not present in Agent 10.0.0.249 2025-08-11 18:06:41,202 - INFO - Validated that VN ctest-vn1-08808345 is not in any agent 2025-08-11 18:06:41,238 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn1-08808345 info 2025-08-11 18:06:41,279 - INFO - Deleted policy policy2 2025-08-11 18:06:41,318 - INFO - Deleted policy policy1 2025-08-11 18:06:42,574 - ERROR - TypeError Python 3.6.8: /usr/bin/python3 Mon Aug 11 18:06:37 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/serial_scripts/vm_regression/test_vm_serial.py in test_process_restart_in_policy_between_vns(self=) 433 434 result = self.verification_after_process_restart_in_rr() 435 assert result[0], result[1] 436 for cfgm_name in self.inputs.cfgm_names: 437 assert self.analytics_obj.verify_cfgm_uve_module_state\ result = True TypeError: 'bool' object is not subscriptable __cause__ = None __class__ = __context__ = None __delattr__ = __dict__ = {} __dir__ = __doc__ = 'Inappropriate argument type.' __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 = ("'bool' object is not subscriptable",) 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/serial_scripts/vm_regression/test_vm_serial.py", line 435, in test_process_restart_in_policy_between_vns assert result[0], result[1] TypeError: 'bool' object is not subscriptable 2025-08-11 18:06:42,574 - DEBUG - Skipping xmpp flap check 2025-08-11 18:06:42,575 - INFO -
2025-08-11 18:06:42,575 - INFO - END TEST : test_process_restart_in_policy_between_vns : FAILED[0:02:51]
2025-08-11 18:06:42,575 - INFO - -------------------------------------------------------------------------------- 2025-08-11 18:06:42,578 - INFO - ================================================================================ 2025-08-11 18:06:42,578 - INFO - STARTING TEST : test_underlay_broadcast_traffic_handling 2025-08-11 18:06:42,579 - INFO - TEST DESCRIPTION : Test the underlay brocast traffic handling by vrouter. (Bug-1545229). 1. Send broadcast traffic from one compute node. 2. Other compute in same subnet should receive that traffic. 3. Receiving compute should treat this traffic as underlay. 4. Compute should not replicate the packet and send the copy back. Pass criteria: Step 3-4 should pass Maintainer : chhandak@juniper.net 2025-08-11 18:06:43,847 - DEBUG - Skipping xmpp flap check 2025-08-11 18:06:43,847 - INFO - Initial checks done. Running the testcase now 2025-08-11 18:06:43,847 - INFO - 2025-08-11 18:06:44,236 - INFO - Agent interface name: ens6 2025-08-11 18:06:44,311 - DEBUG - Executing command: sudo tcpdump -nni ens6 -U host 10.20.0.255 -w /tmp/ens6_ctest-random-06451493.pcap 2025-08-11 18:06:49,760 - INFO - Pinging broacast address 10.20.0.255 from compute 10.20.0.201 2025-08-11 18:07:04,049 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}') 2025-08-11 18:07:06,184 - DEBUG - Executing command: sudo tcpdump -nnr /tmp/ens6_ctest-random-06451493.pcap | grep -c length 2025-08-11 18:07:06,198 - DEBUG - STDOUT: 10 2025-08-11 18:07:06,198 - DEBUG - STDERR: reading from file /tmp/ens6_ctest-random-06451493.pcap, link-type EN10MB (Ethernet), snapshot length 262144 2025-08-11 18:07:06,198 - INFO - 10 packets are found in tcpdump output as expected 2025-08-11 18:07:06,199 - DEBUG - Executing command: sudo kill $(ps -ef|grep tcpdump | grep pcap| awk '{print $2}') 2025-08-11 18:07:08,244 - INFO - Packet count matched: Compute 10.0.0.249 has receive only 10 packet from source IP 10.20.0.255. No duplicate packet seen 2025-08-11 18:07:09,486 - DEBUG - Skipping xmpp flap check
2025-08-11 18:07:09,487 - INFO - END TEST : test_underlay_broadcast_traffic_handling : PASSED[0:00:27]
2025-08-11 18:07:09,487 - INFO - -------------------------------------------------------------------------------- 2025-08-11 18:07:10,215 - INFO - Deleted project: ctest-TestBasicVMVN0-74142812, ID : 95f84723-e259-45f4-a86e-6c35c316e38f