DUT takes more than 7 seconds to finish update ip v6 neighbor

[keboliu]

Description

Steps to reproduce the issue:
run sonic-mgmt test "neighbour_mac_noptf", in this test it use command "ip -6 neigh change xxxxxx" to change the ipv6 neighbor mac address and then verify the ASIC DB to see whether the change is success or not.

Describe the results you received:
sometimes the test failed due to the mac address in the ASIC DB table "KEYS ASIC_STATE:SAI_OBJECT_TYPE_NEIGHBOR_ENTRY*" not change yet, ASIC DB only been updated after about 7 seconds after issue the ip neigh change command.

Describe the results you expected:
the ansible test expecting DB will be updated in 2 seconds, 7 seconds is too long.

Additional information you deem important (e.g. issue happens only occasionally):
when the issue happened, there was no time consuming task running on the DUT, only ansible test is running on it.

Output of show version:

```
admin@sonic:/var/log# show version
SONiC Software Version: SONiC.HEAD.6-6f37181
Distribution: Debian 9.6
Kernel: 4.9.0-8-amd64
Build commit: 6f37181
Build date: Thu Dec 27 09:23:55 UTC 2018
Built by: johnar@jenkins-worker-3

Docker images:
REPOSITORY                 TAG                 IMAGE ID            SIZE
docker-orchagent-mlnx      HEAD.6-6f37181      f7b8bc6db7cd        287.6 MB
docker-orchagent-mlnx      latest              f7b8bc6db7cd        287.6 MB
docker-syncd-mlnx          HEAD.6-6f37181      6e354eba2db0        366 MB
docker-syncd-mlnx          latest              6e354eba2db0        366 MB
docker-lldp-sv2            HEAD.6-6f37181      07af73531c86        275.8 MB
docker-lldp-sv2            latest              07af73531c86        275.8 MB
docker-dhcp-relay          HEAD.6-6f37181      484d63492a27        258 MB
docker-dhcp-relay          latest              484d63492a27        258 MB
docker-database            HEAD.6-6f37181      a946b91f1948        256.7 MB
docker-database            latest              a946b91f1948        256.7 MB
docker-teamd               HEAD.6-6f37181      5b7a15682af1        275.8 MB
docker-teamd               latest              5b7a15682af1        275.8 MB
docker-snmp-sv2            HEAD.6-6f37181      166e335a3a8a        296.9 MB
docker-snmp-sv2            latest              166e335a3a8a        296.9 MB
docker-router-advertiser   HEAD.6-6f37181      d12c47bb6e4e        254.3 MB
docker-router-advertiser   latest              d12c47bb6e4e        254.3 MB
docker-platform-monitor    HEAD.6-6f37181      9027de550971        288.3 MB
docker-platform-monitor    latest              9027de550971        288.3 MB
docker-fpm-quagga          HEAD.6-6f37181      67148e4ecb4b        282.7 MB
docker-fpm-quagga          latest              67148e4ecb4b        282.7 MB
```

syslog for this issue, can see that ip neighbor change command was issued at 06:20:05, ASIC DB was updated at 06:20:11 and 06:20:12, in total it took around 7 seconds:

```
Jan  4 06:20:05.618410 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::62 lladdr 08:bc:27:af:cc:65 dev Ethernet96 removes=None creates=None _uses_shell=False
Jan  4 06:20:05.659794 arc-mtbc-1001 NOTICE swss#orchagent: :- addNeighbor: Updated neighbor 08:bc:27:af:cc:65 on Ethernet96
Jan  4 06:20:05.899714 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::62 lladdr 08:bc:27:af:cc:67 dev Ethernet96 removes=None creates=None _uses_shell=False
Jan  4 06:20:05.920981 arc-mtbc-1001 NOTICE swss#orchagent: :- addNeighbor: Updated neighbor 08:bc:27:af:cc:67 on Ethernet96
Jan  4 06:20:07.987604 arc-mtbc-1001 NOTICE swss#orchagent: :- removeNextHopGroup: Delete next hop group 10.0.0.1,10.0.0.5,10.0.0.9,10.0.0.13,10.0.0.17,10.0.0.21,10.0.0.25,10.0.0.29
Jan  4 06:20:08.327570 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=pgrep orchagent removes=None creates=None _uses_shell=False
Jan  4 06:20:08.853737 arc-mtbc-1001 INFO ansible-<stdin>: Invoked
Jan  4 06:20:09.320123 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=docker exec database redis-cli -n 1 KEYS ASIC_STATE:SAI_OBJECT_TYPE_NEIGHBOR_ENTRY* | grep -Fe '"fc00::62"' removes=None creates=None _uses_shell=True
Jan  4 06:20:09.707769 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=docker exec database redis-cli -n 1 HGETALL 'ASIC_STATE:SAI_OBJECT_TYPE_NEIGHBOR_ENTRY:{"ip":"fc00::62","rif":"oid:0x60000000009d4","switch_id":"oid:0x21000000000000"}' | grep "_ATTR_DST_MAC_ADDRESS" -A 1 | tail -1 removes=None creates=None _uses_shell=True
Jan  4 06:20:11.979943 arc-mtbc-1001 INFO syncd#supervisord: syncd Jan 04 06:20:11 NOTICE  SAI_UTILS: mlnx_sai_utils.c[2290]- set_dispatch_attrib_handler: Set DST_MAC_ADDRESS, key:neighbor ip fc00::62 rif 16, val:[08:bc:27:af:cc:65]
Jan  4 06:20:12.157586 arc-mtbc-1001 INFO syncd#supervisord: syncd Jan 04 06:20:12 NOTICE  SAI_UTILS: mlnx_sai_utils.c[2290]- set_dispatch_attrib_handler: Set DST_MAC_ADDRESS, key:neighbor ip fc00::62 rif 16, val:[08:bc:27:af:cc:67]
```

[liat-grozovik]

@prsunny could you please provide some kind of estimation when this issue can be addressed?
the 'neighbour_mac_noptf' is keep failing and we need this issue to be fixed as part of 201811 release.

[prsunny]

When I tested manually on another platform, I see that the neighbor entry is updated immediately in ASIC DB. Please note the swss and sairedis rec. Can you check the same manually and verify?

ip neigh show
fc00::a dev PortChannel0002 lladdr 52:54:00:28:ff:94 REACHABLE

sudo ip -6 neigh change fc00::a dev PortChannel0002 lladdr 00:54:00:28:ff:94

SWSS Rec

2019-01-31.23:52:35.900837|NEIGH_TABLE:PortChannel0002:fc00::a|SET|neigh:00:54:00:28:ff:94|family:IPv6

SAIREDIS rec
2019-01-31.23:52:35.901075|s|SAI_OBJECT_TYPE_NEIGHBOR_ENTRY:{"ip":"fc00::a","rif":"oid:0x6000000000519","switch_id":"oid:0x21000000000000"}|SAI_NEIGHBOR_ENTRY_ATTR_DST_MAC_ADDRESS=00:54:00:28:FF:94

Syslog:

Jan 31 23:52:35.901447 str-a7170-acs-1 NOTICE swss#orchagent: :- addNeighbor: Updated neighbor 00:54:00:28:ff:94 on PortChannel0002

Notes: This is on the latest master, with T0 topology with BGP sessions up.

[prsunny]

I also tested on the Nov branch, and observed the same result when changing the Neighbor MAC address manually.

[keboliu]

@prsunny thanks for sharing the test result. do you know the flow for the neighbor entry update? I would like to further investigate on our platform.

[keboliu]

@prsunny This issue observed from time to time on our testbed.

In one certain test change the neighbor mac two times

Apr 2 19:15:11.117851 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::62 lladdr 08:bc:27:af:cc:65 dev Ethernet96 removes=None creates=None _uses_shell=False

Apr 2 19:15:11.408204 arc-mtbc-1001 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::62 lladdr 08:bc:27:af:cc:67 dev Ethernet96 removes=None creates=None _uses_shell=False

but only after 10s syncd start to handle the second time change, seems that the first time change was "lost"

Apr 2 19:15:21.249048 arc-mtbc-1001 INFO syncd#supervisord: syncd Apr 02 19:15:21 NOTICE SAI_UTILS: mlnx_sai_utils.c[2307]- set_dispatch_attrib_handler: Set DST_MAC_ADDRESS, key:neighbor ip fc00::62 rif 16, val:[08:bc:27:af:cc:67]

Is it the flow that neighsyncd get neighbor change via RTLINK from kernel and then trigger syncd to finish all the change?

syslog.zip

[liat-grozovik]

@prsunny we cont to see this issue on testbed from time to time. these failures i believe are real and even if it succeed there is something wrong in it.

[stephenxs]

@prsunny
I've built a debug image with some additional logs inserted at the following position:

1. NeighSync::onMsg which is called in neighsyncd when receiving the rtnl message notifying neighbor update from kernel and push it to the APPL_DB.
2. NeighOrch::addNeighbor which is called in orchagent when handling the newly updated/added neighbor and inserting them into ASIC_DB.

I've also add a snippet of code which queries APPL_DB to determine whether the updated mac address has been written into APPL_DB.

Having tested this case on the image, I find:

1. a rtnl message has been received almost immediately once the command is issued, see log below:
   Jun 12 09:42:34.085081 mtbc-sonic-01-2410 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::3e lladdr 08:bc:27:af:cc:65 dev Ethernet60 removes=None creates=None _uses_shell=False
Jun 12 09:42:34.092500 mtbc-sonic-01-2410 INFO swss#neighsyncd: :- onMsg: ND-TEST RECEIVING NLMSG neighbour update Ethernet60:fc00::3e 08:bc:27:af:cc:65
Jun 12 09:42:34.349619 mtbc-sonic-01-2410 INFO ansible-<stdin>: Invoked with warn=True executable=None chdir=None _raw_params=ip -6 neigh change fc00::3e lladdr 08:bc:27:af:cc:67 dev Ethernet60 removes=None creates=None _uses_shell=False
Jun 12 09:42:34.411200 mtbc-sonic-01-2410 INFO swss#neighsyncd: :- onMsg: ND-TEST RECEIVING NLMSG neighbour update Ethernet60:fc00::3e 08:bc:27:af:cc:67
2. According to the log, there is no log indicating the nd has been handled by orchagent(neighagent) before ASIC_DB is checked.
3. The updated mac has not written into APPL_DB either when test failed.

According to the above points, I tend to consider that neighbor update notification has been backlogged in somewhere in orchagent.
Essentially orchagent has a single thread architect which means all work is handled sequentially. Under a heavy workload some work, like neighbor update, can be blocked/delayed if there have already been a lot of works in the queue, which might be what we faced in this issue. Even though under a light workload it can take time to propagate the neighbor update from neighsyncd to orchagent(APPL_DB) and then to syncd(ASIC_DB).
However in the script there is not delay between updating the neighbor in CLI and checking ASIC_DB. I think a 5 second delay should be introduced here in order to solve this issue.

[stepanblyschak]

@prsunny @keboliu @stephenxs
my 2 cents into this issue:

So first in the test goes IPv4 neighbor MAC change test which passes.
This means BGPv4 neighbor will go down because neighbor is not reachable with this MAC so orchagent will go though each route updating next hop group.
While orchagent is updating v4 routes IPv6 neighbor MAC change test starts and orchagent simply has no resources to deal with this update in time.
The idea is to change Neighbor MAC test to configure static neighbors and test, so that it will not affect BGP.

[stephenxs]

@prsunny @keboliu @stephenxs
my 2 cents into this issue:

So first in the test goes IPv4 neighbor MAC change test which passes.
This means BGPv4 neighbor will go down because neighbor is not reachable with this MAC so orchagent will go though each route updating next hop group.
While orchagent is updating v4 routes IPv6 neighbor MAC change test starts and orchagent simply has no resources to deal with this update in time.
The idea is to change Neighbor MAC test to configure static neighbors and test, so that it will not affect BGP.

i think your assumption is reasonable. and to test with a static neighbor is also a good idea.
in addition, as bgp has a hold time of 10 seconds which is long enough for the test, is it possible to recover the mac address of the neighbor at the end of test so that it won't affect the further bgp processing?
also, we can log the bgp neighbor state at the beginning of the test, and also log at the end if failed. by checking the bgp neighbor state before and after the test we can get your assumption proved.

[prsunny]

Closing this as the fix is made as part of referenced commit #1026