Inter-VN ping tests pass after a long time during sanity

[Vedamurthy Joshi]

R4.1.0.0-43 Ubuntu 14.04.5 container setup

DISTRO : "Ubuntu 14.04.5 LTS"
SKU : mitaka
Config Nodes : [u'nodec54']
Control Nodes : [u'nodec54']
Compute Nodes : [u'nodel1', u'nodei10']
Openstack Node : [u'nodec53']
WebUI Node : [u'nodec54']
Analytics Nodes : [u'nodec55', u'nodec56']
Database Nodes : [u'nodec54', u'nodec55', u'nodec56']
Physical Devices : [u'yuvaraj', u"'yuvaraj'"]

VN1 : ctest-vn1-46421628, 128.209.60.0/24, UUID 2ef10b21-fb9b-4499-9614-5d96455d8a07 has VM ctest-vn1-vm1-76279980, f6f8a917-7eb5-4ecf-8233-6143238a5e27 (nodel1) with IP 128.209.60.3

VN2: ctest-vn2-46567432 , 140.190.102.0/24, UUID d6ca1aa4-b9d3-4dc6-9b3c-05726ceb09e5 has VM ctest-vn2-vm1-53970969, 5ea78094-3258-4fc5-8d93-adca81f26e95(on nodei10) , with IP 140.190.102.3

A router was created and these two VNs were attached to the router at this time

2017-09-09 11:22:53,321 - INFO - Adding interface with subnet_id b3f3959a-6a5f-4e5f-b47e-604b5755e00f, port_id None to router 0725c70b-a7a9-4269-b94f-75e1bc294e6f
2017-09-09 11:22:57,501 - INFO - Adding interface with subnet_id e1b462d4-4203-4c32-8c41-3418a97eeb27, port_id None to router 0725c70b-a7a9-4269-b94f-75e1bc294e6f

During the test , Pings between VMs failed till 11:24: and gave up.. When I logged in and I started to ping between VMs, it was failing until 11:39: and started passing from then on

From the flow logs, it was failing till 11:39 due to ‘No route for Dst-IP’ … and looks like the route got added then, after which things were fine.
The Ksync-Route, ControllerRxRouteXmppMessage1, Flow traces are in http://10.204.216.50/Docs/bugs/#
Gcores of control-node and agent of nodel1 are at http://10.204.216.50/Docs/bugs/#

Test log :

2017-09-09 11:21:44,229 - INFO - Initial checks done. Running the testcase now
2017-09-09 11:21:44,229 - INFO -
2017-09-09 11:21:46,176 - DEBUG - Response for create_network : {u'network': {u'status': u'ACTIVE', u'router:external': False, u'subnets': [], u'fq_name': [u'default-domain', u'ctest-TestRouters-09936244', u'ctest-vn1-46421628'], u'name': u'ctest-vn1-46421628', u'admin_state_up': True, u'tenant_id': u'7fb3b1dacdac41a2b3c475df6becf5f0', u'created_at': None, u'updated_at': None, u'shared': False, u'port_security_enabled': True, u'id': u'2ef10b21-fb9b-4499-9614-5d96455d8a07', u'description': u''}}
2017-09-09 11:21:47,457 - DEBUG - Response for create_subnet : {u'subnet': {u'name': u'', u'enable_dhcp': True, u'network_id': u'2ef10b21-fb9b-4499-9614-5d96455d8a07', u'tenant_id': u'7fb3b1dacdac41a2b3c475df6becf5f0', u'created_at': u'2017-09-09T05:51:46.817691', u'dns_nameservers': [], u'updated_at': u'2017-09-09T05:51:46.817691', u'gateway_ip': u'128.209.60.1', u'ipv6_ra_mode': None, u'allocation_pools': [{u'start': u'128.209.60.2', u'end': u'128.209.60.254'}], u'host_routes': [], u'dns_server_address': u'128.209.60.2', u'ip_version': 4, u'ipv6_address_mode': None, u'cidr': u'128.209.60.0/24', u'id': u'b3f3959a-6a5f-4e5f-b47e-604b5755e00f'}}
2017-09-09 11:21:47,912 - INFO - Created VN ctest-vn1-46421628
2017-09-09 11:21:48,283 - DEBUG - VN ctest-vn1-46421628 UUID is 2ef10b21-fb9b-4499-9614-5d96455d8a07
2017-09-09 11:21:51,241 - DEBUG - Response for create_network : {u'network': {u'status': u'ACTIVE', u'router:external': False, u'subnets': [], u'fq_name': [u'default-domain', u'ctest-TestRouters-09936244', u'ctest-vn2-46567432'], u'name': u'ctest-vn2-46567432', u'admin_state_up': True, u'tenant_id': u'7fb3b1dacdac41a2b3c475df6becf5f0', u'created_at': None, u'updated_at': None, u'shared': False, u'port_security_enabled': True, u'id': u'd6ca1aa4-b9d3-4dc6-9b3c-05726ceb09e5', u'description': u''}}
2017-09-09 11:21:52,304 - DEBUG - Response for create_subnet : {u'subnet': {u'name': u'', u'enable_dhcp': True, u'network_id': u'd6ca1aa4-b9d3-4dc6-9b3c-05726ceb09e5', u'tenant_id': u'7fb3b1dacdac41a2b3c475df6becf5f0', u'created_at': u'2017-09-09T05:51:51.708470', u'dns_nameservers': [], u'updated_at': u'2017-09-09T05:51:51.708470', u'gateway_ip': u'140.190.102.1', u'ipv6_ra_mode': None, u'allocation_pools': [{u'start': u'140.190.102.2', u'end': u'140.190.102.254'}], u'host_routes': [], u'dns_server_address': u'140.190.102.2', u'ip_version': 4, u'ipv6_address_mode': None, u'cidr': u'140.190.102.0/24', u'id': u'e1b462d4-4203-4c32-8c41-3418a97eeb27'}}
2017-09-09 11:21:52,762 - INFO - Created VN ctest-vn2-46567432
2017-09-09 11:21:53,005 - DEBUG - VN ctest-vn2-46567432 UUID is d6ca1aa4-b9d3-4dc6-9b3c-05726ceb09e5
2017-09-09 11:21:59,345 - DEBUG - Services list from nova: [<Service: nova-conductor>, <Service: nova-scheduler>, <Service: nova-consoleauth>, <Service: nova-console>, <Service: nova-compute>, <Service: nova-compute>]
2017-09-09 11:21:59,568 - DEBUG - Check whether image by uuid a6b21d64-e3cc-4d57-ba91-7f0ad838c283 is active
2017-09-09 11:22:05,027 - INFO - VM ([<Server: ctest-vn1-vm1-76279980>]) created on node: (nodel1), Zone: (nova:nodel1)
2017-09-09 11:22:10,906 - DEBUG - Check whether image by uuid a6b21d64-e3cc-4d57-ba91-7f0ad838c283 is active
2017-09-09 11:22:16,323 - INFO - VM ([<Server: ctest-vn2-vm1-53970969>]) created on node: (nodei10), Zone: (nova:nodei10)
2017-09-09 11:22:16,323 - INFO - Waiting for VM ctest-vn1-vm1-76279980 to be up..
2017-09-09 11:22:18,176 - DEBUG - VM <Server: ctest-vn1-vm1-76279980> is in ACTIVE state now
2017-09-09 11:22:20,036 - DEBUG - VM ctest-vn1-vm1-76279980 ID is f6f8a917-7eb5-4ecf-8233-6143238a5e27
2017-09-09 11:22:20,058 - DEBUG - VM ctest-vn1-vm1-76279980 launched on Node nodel1
2017-09-09 11:22:24,127 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine/f6f8a917-7eb5-4ecf-8233-6143238a5e27
2017-09-09 11:22:24,299 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine/f6f8a917-7eb5-4ecf-8233-6143238a5e27
2017-09-09 11:22:24,394 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine-interface/dea1a5a2-3ccb-4400-821b-36d50a24192b
2017-09-09 11:22:24,491 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine/f6f8a917-7eb5-4ecf-8233-6143238a5e27
2017-09-09 11:22:24,586 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine-interface/dea1a5a2-3ccb-4400-821b-36d50a24192b
2017-09-09 11:22:26,096 - DEBUG - (True, 'PING 169.254.0.6 (169.254.0.6) 56(84) bytes of data.\r\n64 bytes from 169.254.0.6: icmp_seq=1 ttl=63 time=0.474 ms\r\n64 bytes from 169.254.0.6: icmp_seq=2 ttl=63 time=0.111 ms\r\n\r\n--- 169.254.0.6 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 999ms\r\nrtt min/avg/max/mdev = 0.111/0.292/0.474/0.182 ms')
2017-09-09 11:22:26,096 - INFO - Ping to Metadata IP 169.254.0.6 of VM ctest-vn1-vm1-76279980 passed
2017-09-09 11:22:26,461 - DEBUG - Waiting to SSH to VM ctest-vn1-vm1-76279980, IP 128.209.60.3
2017-09-09 11:22:31,509 - DEBUG - VM ctest-vn1-vm1-76279980 is ready for SSH connections
2017-09-09 11:22:31,510 - INFO - Waiting for VM ctest-vn2-vm1-53970969 to be up..
2017-09-09 11:22:33,377 - DEBUG - VM <Server: ctest-vn2-vm1-53970969> is in ACTIVE state now
2017-09-09 11:22:35,046 - DEBUG - VM ctest-vn2-vm1-53970969 ID is 5ea78094-3258-4fc5-8d93-adca81f26e95
2017-09-09 11:22:35,046 - DEBUG - VM ctest-vn2-vm1-53970969 launched on Node nodei10
2017-09-09 11:22:38,929 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine/5ea78094-3258-4fc5-8d93-adca81f26e95
2017-09-09 11:22:39,028 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine-interface/09e0bc74-82df-4870-b7e8-8ee299f3f8d2
2017-09-09 11:22:39,121 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine/5ea78094-3258-4fc5-8d93-adca81f26e95
2017-09-09 11:22:39,207 - DEBUG - Requesting: http://10.204.217.94:8082/virtual-machine-interface/09e0bc74-82df-4870-b7e8-8ee299f3f8d2
2017-09-09 11:22:40,692 - 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=1.51 ms\r\n64 bytes from 169.254.0.4: icmp_seq=2 ttl=63 time=0.223 ms\r\n\r\n--- 169.254.0.4 ping statistics ---\r\n2 packets transmitted, 2 received, 0% packet loss, time 1001ms\r\nrtt min/avg/max/mdev = 0.223/0.870/1.517/0.647 ms')
2017-09-09 11:22:40,692 - INFO - Ping to Metadata IP 169.254.0.4 of VM ctest-vn2-vm1-53970969 passed
2017-09-09 11:22:41,074 - DEBUG - Waiting to SSH to VM ctest-vn2-vm1-53970969, IP 140.190.102.3
2017-09-09 11:22:46,129 - DEBUG - VM ctest-vn2-vm1-53970969 is ready for SSH connections
2017-09-09 11:22:46,424 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:22:46,425 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:22:52,028 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
--- 140.190.102.3 ping statistics ---^M
5 packets transmitted, 0 packets received, 100% packet loss
2017-09-09 11:22:52,028 - WARNING - Ping to IP 140.190.102.3 from VM ctest-vn1-vm1-76279980 failed
2017-09-09 11:22:53,321 - INFO - Adding interface with subnet_id b3f3959a-6a5f-4e5f-b47e-604b5755e00f, port_id None to router 0725c70b-a7a9-4269-b94f-75e1bc294e6f
2017-09-09 11:22:57,501 - INFO - Adding interface with subnet_id e1b462d4-4203-4c32-8c41-3418a97eeb27, port_id None to router 0725c70b-a7a9-4269-b94f-75e1bc294e6f
2017-09-09 11:23:04,728 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:23:04,729 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:23:10,410 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
--- 140.190.102.3 ping statistics ---^M
5 packets transmitted, 0 packets received, 100% packet loss
2017-09-09 11:23:10,410 - WARNING - Ping to IP 140.190.102.3 from VM ctest-vn1-vm1-76279980 failed
2017-09-09 11:23:11,541 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:23:11,542 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:23:17,158 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
--- 140.190.102.3 ping statistics ---^M
5 packets transmitted, 0 packets received, 100% packet loss
2017-09-09 11:23:17,158 - WARNING - Ping to IP 140.190.102.3 from VM ctest-vn1-vm1-76279980 failed
2017-09-09 11:23:18,281 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:23:18,281 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:23:23,931 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
-- 140.190.102.3 ping statistics ---^M
5 packets transmitted, 0 packets received, 100% packet loss
2017-09-09 11:23:23,931 - WARNING - Ping to IP 140.190.102.3 from VM ctest-vn1-vm1-76279980 failed
2017-09-09 11:23:25,061 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:23:25,061 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:23:30,733 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
--- 140.190.102.3 ping statistics ---^M
5 packets transmitted, 0 packets received, 100% packet loss
2017-09-09 11:23:30,733 - WARNING - Ping to IP 140.190.102.3 from VM ctest-vn1-vm1-76279980 failed
2017-09-09 11:23:31,856 - DEBUG - Running remote_cmd, Cmd : ping -s 56 -c 5 -W 1 140.190.102.3, host_string: cirros@169.254.0.6, password: cubswin:)gateway: root@10.204.217.206, gateway password: c0ntrail123
2017-09-09 11:23:31,856 - DEBUG - ping -s 56 -c 5 -W 1 140.190.102.3
2017-09-09 11:23:37,460 - DEBUG - PING 140.190.102.3 (140.190.102.3): 56 data bytes^M
^M
--- 140.190.102.3 ping statistics ---^M
--------------------------------