2025-07-21 14:34:56,063 - INFO - Domain Default found not creating 2025-07-21 14:34:56,396 - INFO - Project ctest-TestBasicVMVN0-10964766 not found, creating it 2025-07-21 14:34:57,258 - INFO - Created Project:ctest-TestBasicVMVN0-10964766, ID : 7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:34:59,590 - INFO - ================================================================================ 2025-07-21 14:34:59,591 - INFO - STARTING TEST : test_control_node_switchover 2025-07-21 14:34:59,591 - 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-07-21 14:34:59,783 - DEBUG - Skipping xmpp flap check 2025-07-21 14:34:59,783 - INFO - Initial checks done. Running the testcase now 2025-07-21 14:34:59,783 - INFO - 2025-07-21 14:34:59,784 - INFO - Skipping Test. At least 2 control node required to run the test 2025-07-21 14:34:59,784 - INFO - Skipping Test. At least 2 control node required to run the test 2025-07-21 14:34:59,997 - DEBUG - Skipping xmpp flap check 2025-07-21 14:34:59,997 - INFO -
2025-07-21 14:34:59,997 - INFO - END TEST : test_control_node_switchover : SKIPPED[0:00:00]
2025-07-21 14:34:59,997 - INFO - -------------------------------------------------------------------------------- 2025-07-21 14:35:00,001 - INFO - ================================================================================ 2025-07-21 14:35:00,002 - INFO - STARTING TEST : test_process_restart_in_policy_between_vns 2025-07-21 14:35:00,002 - 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-07-21 14:35:00,200 - DEBUG - Skipping xmpp flap check 2025-07-21 14:35:00,200 - INFO - Initial checks done. Running the testcase now 2025-07-21 14:35:00,200 - INFO - 2025-07-21 14:35:00,562 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = icmp, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764, 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-10964766:ctest-vn2-90436688, 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-07-21 14:35:00,861 - DEBUG - Policy np_rules : [rule_sequence = None, rule_uuid = None, direction = <>, protocol = icmp, src_addresses = [subnet = None, virtual_network = default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688, 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-10964766:ctest-vn1-06566764, 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-07-21 14:35:01,560 - INFO - Created VN ctest-vn1-06566764, UUID :a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:01,912 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:35:02,212 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:35:02,254 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:35:02,270 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:35:02,379 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,396 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,414 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:35:02,426 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:35:02,439 - DEBUG - Requesting: http://10.0.0.254:8082/route-target/515e4166-8bda-4d28-a5fa-b4d5e2c73b6e 2025-07-21 14:35:02,450 - DEBUG - Route Targets: ['target:64512:8000013'] 2025-07-21 14:35:02,450 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,465 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:35:02,490 - INFO - Verified VN network id 18 for VN a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,490 - INFO - Verifications in API Server for VN ctest-vn1-06566764 passed 2025-07-21 14:35:02,490 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,503 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:35:02,512 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:35:02,521 - DEBUG - Requesting: http://10.0.0.254:8082/route-target/515e4166-8bda-4d28-a5fa-b4d5e2c73b6e 2025-07-21 14:35:02,542 - DEBUG - Control-node 10.0.0.254 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-10964766', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '12234030252689213297', 'uuid-lslong': '10901846673150547769'}, 'enable': 'true', 'created': '2025-07-21T14:35:01', 'last-modified': '2025-07-21T14:35:01', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.823833'} 2025-07-21 14:35:02,551 - DEBUG - Route Targets: ['target:64512:8000013'] 2025-07-21 14:35:02,551 - INFO - On all control nodes, Config, RI and RT verification for VN ctest-vn1-06566764 passed 2025-07-21 14:35:02,552 - DEBUG - ====Verifying policy data for ctest-vn1-06566764 in API_Server ====== 2025-07-21 14:35:02,552 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:35:02,562 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:35:02,579 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:35:02,684 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/a9c801b2-36ec-4771-974b-23c9ece99739 2025-07-21 14:35:02,706 - DEBUG - =>VN ctest-vn1-06566764 has no policy to be verified 2025-07-21 14:35:02,706 - DEBUG - Verifying the vn in opserver 2025-07-21 14:35:02,706 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 virtual network link through opserver 10.0.0.254 2025-07-21 14:35:02,706 - DEBUG - Requesting: http://10.0.0.254:8081/analytics/uves/virtual-networks 2025-07-21 14:35:03,037 - DEBUG - Requesting: http://10.0.0.254:8081/analytics/uves/virtual-networks 2025-07-21 14:35:03,137 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764', 'href': 'http://10.0.0.254:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764?flat'} 2025-07-21 14:35:03,138 - INFO - Validated that VN default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is found in opserver 2025-07-21 14:35:03,170 - DEBUG - Do not have enough data to verify VN in agent 2025-07-21 14:35:03,185 - DEBUG - VRF ids for VN ctest-vn1-06566764: {} 2025-07-21 14:35:04,089 - INFO - Created VN ctest-vn2-90436688, UUID :9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,546 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:35:04,562 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:35:04,597 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:35:04,737 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,770 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,798 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:35:04,812 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:35:04,827 - DEBUG - Requesting: http://10.0.0.254:8082/route-target/6b6e29dd-3da4-4475-89fa-24c55ffa1caf 2025-07-21 14:35:04,844 - DEBUG - Route Targets: ['target:64512:8000014'] 2025-07-21 14:35:04,844 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,872 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:35:04,917 - INFO - Verified VN network id 19 for VN 9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,918 - INFO - Verifications in API Server for VN ctest-vn2-90436688 passed 2025-07-21 14:35:04,918 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:04,939 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:35:04,957 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:35:04,976 - DEBUG - Requesting: http://10.0.0.254:8082/route-target/6b6e29dd-3da4-4475-89fa-24c55ffa1caf 2025-07-21 14:35:05,016 - DEBUG - Control-node 10.0.0.254 : VN object is : {'node_name': 'virtual-network:default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688', 'interests': '-', 'advertised': '-', 'dbentryflags': None, 'obj_info': {'sequence_number': '0', 'origin': 'Cassandra', 'data': {'id-perms': {'permissions': {'owner': 'ctest-TestBasicVMVN0-10964766', 'owner-access': '7', 'group': 'member', 'group-access': '7', 'other-access': '7'}, 'uuid': {'uuid-mslong': '11150762886161387288', 'uuid-lslong': '10640484277664198965'}, 'enable': 'true', 'created': '2025-07-21T14:35:03', 'last-modified': '2025-07-21T14:35:04', 'description': None, 'user-visible': 'true', 'creator': None}}}, 'neighbors': None, 'last_modified': '00:00:00.772424'} 2025-07-21 14:35:05,040 - DEBUG - Route Targets: ['target:64512:8000014'] 2025-07-21 14:35:05,040 - INFO - On all control nodes, Config, RI and RT verification for VN ctest-vn2-90436688 passed 2025-07-21 14:35:05,041 - DEBUG - ====Verifying policy data for ctest-vn2-90436688 in API_Server ====== 2025-07-21 14:35:05,041 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:35:05,060 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:35:05,100 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:35:05,223 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-network/9abf77c4-0442-4f18-93aa-9813284db135 2025-07-21 14:35:05,248 - DEBUG - =>VN ctest-vn2-90436688 has no policy to be verified 2025-07-21 14:35:05,248 - DEBUG - Verifying the vn in opserver 2025-07-21 14:35:05,248 - DEBUG - Verifying the default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688 virtual network link through opserver 10.0.0.254 2025-07-21 14:35:05,248 - DEBUG - Requesting: http://10.0.0.254:8081/analytics/uves/virtual-networks 2025-07-21 14:35:05,274 - DEBUG - vn link and name as {'name': 'default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688', 'href': 'http://10.0.0.254:8081/analytics/uves/virtual-network/default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688?flat'} 2025-07-21 14:35:05,274 - INFO - Validated that VN default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn2-90436688 is found in opserver 2025-07-21 14:35:05,306 - DEBUG - Do not have enough data to verify VN in agent 2025-07-21 14:35:05,324 - DEBUG - VRF ids for VN ctest-vn2-90436688: {} 2025-07-21 14:35:06,079 - DEBUG - Services list from nova: [, , ] 2025-07-21 14:35:07,856 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-3677-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-3677-1) 2025-07-21 14:35:09,655 - INFO - VM ([]) created on node: (cn-jenkins-deploy-platform-ansible-os-3677-1), Zone: (nova:cn-jenkins-deploy-platform-ansible-os-3677-1) 2025-07-21 14:35:09,655 - INFO - Waiting for VM ctest-vn1_vm1-89599206 to be up.. 2025-07-21 14:35:09,769 - DEBUG - VM is still in BUILD state, Expected: ACTIVE 2025-07-21 14:35:14,978 - DEBUG - VM is in ACTIVE state now 2025-07-21 14:35:14,979 - INFO - VM name : ctest-vn1_vm1-89599206 2025-07-21 14:35:15,169 - DEBUG - VM ctest-vn1_vm1-89599206 ID is a6eeaea0-5d9a-473d-9acd-e27b5245f1c8 2025-07-21 14:35:15,220 - DEBUG - VM ctest-vn1_vm1-89599206 launched on Node cn-jenkins-deploy-platform-ansible-os-3677-1. 2025-07-21 14:35:15,397 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-machine/a6eeaea0-5d9a-473d-9acd-e27b5245f1c8 2025-07-21 14:35:15,414 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-machine-interface/2250b7c2-3d61-4488-b476-41cb8ff9c934 2025-07-21 14:35:18,679 - 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 1024ms') 2025-07-21 14:35:18,680 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:18,754 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:22,806 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1010ms') 2025-07-21 14:35:22,806 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:22,885 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:26,937 - 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 1012ms') 2025-07-21 14:35:26,938 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:27,017 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:31,062 - 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-07-21 14:35:31,062 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:31,138 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:35,191 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1021ms') 2025-07-21 14:35:35,191 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:35,277 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:39,316 - 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 1001ms') 2025-07-21 14:35:39,316 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:39,389 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:43,450 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1030ms') 2025-07-21 14:35:43,450 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:43,525 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:47,578 - 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-07-21 14:35:47,579 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:47,661 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:51,734 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 0 received, 100% packet loss, time 1030ms') 2025-07-21 14:35:51,734 - DEBUG - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 failed! 2025-07-21 14:35:51,805 - DEBUG - Gateway for vn default-domain:ctest-TestBasicVMVN0-10964766:ctest-vn1-06566764 is 192.168.1.254 and allocation pool is NOT set 2025-07-21 14:35:53,851 - DEBUG - (True, 'PING 169.254.0.3 (169.254.0.3) 56(84) bytes of data.\r\n64 bytes from 169.254.0.3: icmp_seq=1 ttl=63 time=7.11 ms\r\n64 bytes from 169.254.0.3: icmp_seq=2 ttl=63 time=0.881 ms\r\n\r\n--- 169.254.0.3 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 0.881/3.993/7.106/3.112 ms') 2025-07-21 14:35:53,851 - INFO - Ping to Metadata IP 169.254.0.3 of VM ctest-vn1_vm1-89599206 passed 2025-07-21 14:35:54,045 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:35:54,045 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-89599206, IP 192.168.1.252, Port 22 2025-07-21 14:35:54,083 - 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-07-21 14:35:54,384 - DEBUG - VM ctest-vn1_vm1-89599206 is NOT ready for SSH connections, VM status: ACTIVE 2025-07-21 14:35:59,386 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:35:59,386 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-89599206, IP 192.168.1.252, Port 22 2025-07-21 14:35:59,426 - 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-07-21 14:35:59,584 - DEBUG - VM ctest-vn1_vm1-89599206 is NOT ready for SSH connections, VM status: ACTIVE 2025-07-21 14:36:04,585 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:36:04,586 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-89599206, IP 192.168.1.252, Port 22 2025-07-21 14:36:04,611 - 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-07-21 14:36:04,724 - DEBUG - VM ctest-vn1_vm1-89599206 is NOT ready for SSH connections, VM status: ACTIVE 2025-07-21 14:36:09,724 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:36:09,725 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-89599206, IP 192.168.1.252, Port 22 2025-07-21 14:36:09,766 - 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-07-21 14:36:09,956 - DEBUG - VM ctest-vn1_vm1-89599206 is NOT ready for SSH connections, VM status: ACTIVE 2025-07-21 14:36:14,958 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:36:14,958 - DEBUG - Waiting to SSH to VM ctest-vn1_vm1-89599206, IP 192.168.1.252, Port 22 2025-07-21 14:36:15,066 - DEBUG - VM ctest-vn1_vm1-89599206 is ready for SSH connections 2025-07-21 14:36:15,066 - INFO - Waiting for VM ctest-vn2_vm1-98260232 to be up.. 2025-07-21 14:36:15,247 - DEBUG - VM is in ACTIVE state now 2025-07-21 14:36:15,247 - INFO - VM name : ctest-vn2_vm1-98260232 2025-07-21 14:36:15,394 - DEBUG - VM ctest-vn2_vm1-98260232 ID is 88c310c0-d47c-4d6b-b1a7-812ef7f570e9 2025-07-21 14:36:15,394 - DEBUG - VM ctest-vn2_vm1-98260232 launched on Node cn-jenkins-deploy-platform-ansible-os-3677-1. 2025-07-21 14:36:15,474 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-machine/88c310c0-d47c-4d6b-b1a7-812ef7f570e9 2025-07-21 14:36:15,487 - DEBUG - Requesting: http://10.0.0.254:8082/virtual-machine-interface/6da4d71f-cbff-4038-99e3-85542c75ca45 2025-07-21 14:36:16,740 - DEBUG - (True, 'PING 169.254.0.4 (169.254.0.4) 56(84) bytes of data.\r\n64 bytes from 169.254.0.4: icmp_seq=1 ttl=63 time=13.7 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=3.91 ms\r\n\r\n--- 169.254.0.4 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1002ms\r\nrtt min/avg/max/mdev = 3.906/8.824/13.743/4.918 ms') 2025-07-21 14:36:16,741 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-vn2_vm1-98260232 passed 2025-07-21 14:36:16,941 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:36:16,941 - DEBUG - Waiting to SSH to VM ctest-vn2_vm1-98260232, IP 192.168.2.252, Port 22 2025-07-21 14:36:17,055 - DEBUG - VM ctest-vn2_vm1-98260232 is ready for SSH connections 2025-07-21 14:36:17,055 - DEBUG - verify_vm_launched is skipped since self.vm_launch_flag is set 2025-07-21 14:36:17,055 - 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.254, gateway password: c0ntrail123 2025-07-21 14:36:17,056 - DEBUG - ping -s 56 -c 3 -W 1 192.168.2.252 2025-07-21 14:36:40,332 - 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=6.21 ms 64 bytes from 192.168.2.252: icmp_req=2 ttl=63 time=11.7 ms 64 bytes from 192.168.2.252: icmp_req=3 ttl=63 time=0.851 ms --- 192.168.2.252 ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2003ms rtt min/avg/max/mdev = 0.851/6.269/11.743/4.447 ms 2025-07-21 14:36:40,332 - INFO - Ping to IP 192.168.2.252 from VM ctest-vn1_vm1-89599206 passed 2025-07-21 14:36:43,867 - INFO - 10.0.0.254 2025-07-21 14:36:43,871 - INFO - agent:initializing 2025-07-21 14:36:43,871 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': None}}}) 2025-07-21 14:36:43,871 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 0 2025-07-21 14:36:48,980 - INFO - 10.0.0.254 2025-07-21 14:36:48,988 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:36:48,988 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:36:48,988 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 1 2025-07-21 14:36:54,193 - INFO - 10.0.0.254 2025-07-21 14:36:54,211 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:36:54,212 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:36:54,212 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 2 2025-07-21 14:36:59,423 - INFO - 10.0.0.254 2025-07-21 14:36:59,438 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:36:59,438 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:36:59,438 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 3 2025-07-21 14:37:04,612 - INFO - 10.0.0.254 2025-07-21 14:37:04,627 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:04,627 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:04,628 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 4 2025-07-21 14:37:09,841 - INFO - 10.0.0.254 2025-07-21 14:37:09,859 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:09,859 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:09,860 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 5 2025-07-21 14:37:15,058 - INFO - 10.0.0.254 2025-07-21 14:37:15,071 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:15,071 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:15,071 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 6 2025-07-21 14:37:20,279 - INFO - 10.0.0.254 2025-07-21 14:37:20,296 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:20,296 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:20,297 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 7 2025-07-21 14:37:25,482 - INFO - 10.0.0.254 2025-07-21 14:37:25,501 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:25,501 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:25,501 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 8 2025-07-21 14:37:30,698 - INFO - 10.0.0.254 2025-07-21 14:37:30,715 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:30,715 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:30,715 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 9 2025-07-21 14:37:35,926 - INFO - 10.0.0.254 2025-07-21 14:37:35,951 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:35,952 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:35,952 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 10 2025-07-21 14:37:41,158 - INFO - 10.0.0.254 2025-07-21 14:37:41,177 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:41,177 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:41,178 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 11 2025-07-21 14:37:46,408 - INFO - 10.0.0.254 2025-07-21 14:37:46,417 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:46,417 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:46,417 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 12 2025-07-21 14:37:51,622 - INFO - 10.0.0.254 2025-07-21 14:37:51,640 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:51,641 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:51,641 - DEBUG - Not all services up. Sleeping for 5 seconds. iteration: 13 2025-07-21 14:37:56,850 - INFO - 10.0.0.254 2025-07-21 14:37:56,872 - INFO - agent:initializing (No Configuration for self) 2025-07-21 14:37:56,872 - DEBUG - defaultdict(, {'10.0.0.254': {'agent': {'status': 'initializing', 'description': 'No Configuration for self'}}}) 2025-07-21 14:37:56,872 - ERROR - Not all services up , Gave up! 2025-07-21 14:37:56,879 - INFO - Deleting VM ctest-vn2_vm1-98260232 2025-07-21 14:37:57,085 - INFO - Deleting VM ctest-vn1_vm1-89599206 2025-07-21 14:37:57,527 - INFO - Deleting VN ctest-vn2-90436688 2025-07-21 14:37:57,601 - DEBUG - RefsExistError Delete when resource still referred: ['http://10.0.0.254:8082/instance-ip/46a19dfe-c869-49d2-9f21-d8627f3daed8'] while deleting VN ctest-vn2-90436688..Will retry 2025-07-21 14:37:59,802 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/ef383192-a41b-4fc3-8a24-b1b13d302915 2025-07-21 14:37:59,810 - DEBUG - Response Code: 404 2025-07-21 14:37:59,810 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:37:59,819 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:37:59,899 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:38:00,025 - INFO - Validated that VN ctest-vn2-90436688 is not found in API Server 2025-07-21 14:38:00,065 - DEBUG - VN ctest-vn2-90436688 is not present in Agent 10.0.0.254 2025-07-21 14:38:00,065 - INFO - Validated that VN ctest-vn2-90436688 is not in any agent 2025-07-21 14:38:00,113 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn2-90436688 info 2025-07-21 14:38:00,389 - INFO - Deleting VN ctest-vn1-06566764 2025-07-21 14:38:00,547 - DEBUG - Requesting: http://10.0.0.254:8082/routing-instance/f417dfe8-a7d7-4e02-ac4f-f99e9a5877ec 2025-07-21 14:38:00,559 - DEBUG - Response Code: 404 2025-07-21 14:38:00,560 - DEBUG - Requesting: http://10.0.0.254:8082/domains 2025-07-21 14:38:00,570 - DEBUG - Requesting: http://10.0.0.254:8082/domain/6f2dbf83-3a1f-4a4f-8676-305ebe4efd33 2025-07-21 14:38:00,598 - DEBUG - Requesting: http://10.0.0.254:8082/project/7902caf8-58f2-428c-a4aa-0085e08a4b9a 2025-07-21 14:38:00,703 - INFO - Validated that VN ctest-vn1-06566764 is not found in API Server 2025-07-21 14:38:00,737 - DEBUG - VN ctest-vn1-06566764 is not present in Agent 10.0.0.254 2025-07-21 14:38:00,737 - INFO - Validated that VN ctest-vn1-06566764 is not in any agent 2025-07-21 14:38:00,792 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn1-06566764 info 2025-07-21 14:38:00,864 - INFO - Deleted policy policy2 2025-07-21 14:38:00,901 - INFO - Deleted policy policy1 2025-07-21 14:38:01,199 - ERROR - AssertionError Python 3.6.8: /usr/bin/python3 Mon Jul 21 14:37:56 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=) 426 else: 427 self.inputs.restart_service('contrail-vrouter-agent', [compute_ip], 428 container='agent') 429 for bgp_ip in self.inputs.bgp_ips: 430 self.inputs.restart_service('contrail-control', [bgp_ip], container undefined /contrail-test/common/contrail_test_init.py in restart_service(self=, service_name='contrail-vrouter-agent', host_ips=['10.0.0.254'], container='agent', verify_service=True) 1374 container=None, verify_service=True): 1375 self._action_on_service(service_name, 'restart', host_ips, container, 1376 verify_service=verify_service) 1377 # end restart_service 1378 verify_service = True /contrail-test/common/contrail_test_init.py in _action_on_service(self=, service_name='contrail-vrouter-agent', event='restart', host_ips=['10.0.0.254'], container='agent', verify_service=True) 1362 if self.is_microservices_env and container: 1363 return self._action_on_container(host_ips, event, container, services=services, 1364 verify_service=verify_service) 1365 for service in services: 1366 for host in host_ips or self.host_ips: verify_service = True /contrail-test/common/contrail_test_init.py in _action_on_container(self=, hosts=['10.0.0.254'], event='restart', container='agent', services=['contrail-vrouter-agent'], verify_service=True, timeout=60) 1322 else: 1323 service_status = self.verify_service_state(host_ip, container)[0] 1324 assert service_status 1325 #end _action_on_container 1326 service_status = False AssertionError: __cause__ = None __class__ = __context__ = None __delattr__ = __dict__ = {} __dir__ = __doc__ = 'Assertion failed.' __eq__ = __format__ = __ge__ = __getattribute__ = __gt__ = __hash__ = __init__ = __init_subclass__ = __le__ = __lt__ = __ne__ = __new__ = __reduce__ = __reduce_ex__ = __repr__ = __setattr__ = __setstate__ = __sizeof__ = __str__ = __subclasshook__ = __suppress_context__ = False __traceback__ = args = () with_traceback = The above is a description of an error in a Python program. Here is the original traceback: Traceback (most recent call last): File "/contrail-test/tcutils/wrappers.py", line 80, in wrapper result = function(self, *args, **kwargs) File "/contrail-test/serial_scripts/vm_regression/test_vm_serial.py", line 428, in test_process_restart_in_policy_between_vns container='agent') File "/contrail-test/common/contrail_test_init.py", line 1376, in restart_service verify_service=verify_service) File "/contrail-test/common/contrail_test_init.py", line 1364, in _action_on_service verify_service=verify_service) File "/contrail-test/common/contrail_test_init.py", line 1324, in _action_on_container assert service_status AssertionError 2025-07-21 14:38:01,200 - DEBUG - Skipping xmpp flap check 2025-07-21 14:38:01,201 - INFO -
2025-07-21 14:38:01,201 - INFO - END TEST : test_process_restart_in_policy_between_vns : FAILED[0:03:01]
2025-07-21 14:38:01,201 - INFO - -------------------------------------------------------------------------------- 2025-07-21 14:38:01,214 - INFO - ================================================================================ 2025-07-21 14:38:01,214 - INFO - STARTING TEST : test_underlay_broadcast_traffic_handling 2025-07-21 14:38:01,215 - 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-07-21 14:38:01,550 - DEBUG - Skipping xmpp flap check 2025-07-21 14:38:01,551 - INFO - Initial checks done. Running the testcase now 2025-07-21 14:38:01,551 - INFO - 2025-07-21 14:38:01,551 - INFO - Skipping Test. At least 2 compute node required to run the test 2025-07-21 14:38:01,878 - DEBUG - Skipping xmpp flap check 2025-07-21 14:38:01,879 - INFO -
2025-07-21 14:38:01,879 - INFO - END TEST : test_underlay_broadcast_traffic_handling : SKIPPED[0:00:00]
2025-07-21 14:38:01,879 - INFO - -------------------------------------------------------------------------------- 2025-07-21 14:38:02,692 - INFO - Deleted project: ctest-TestBasicVMVN0-10964766, ID : 7902caf8-58f2-428c-a4aa-0085e08a4b9a