Port status not reflected in SONiC

[ciju-juniper]

Description

This is an issue observed in the latest SONiC images. When the cables are connected/removed in the switch ports, interface status is not correctly reflected in 'show interfaces status'. Link status is updated correctly in the broadcom side. Changes in the link state are not updated in the kernel. The files '/sys/class/net/Ethernet*/carrier' are not updated whenever the OIR is done. After a system reboot, the link status is updated in the kernel and SONiC is able to report the status correctly.

We tried to narrow down this problem to a specific kernel version, but the SONiC builds are broken when we go back to couple of weeks / months due to certain package versions missing.
The last commit on which we didn't observe this issue was on Feb-26 and there are quite significant changes happened in 'drivers/net' directory of the kernel in the span of 1.5 months.

Please have a look on this issue and suggest how to debug further.

Testing environment

Switch: QFX5200-32C-S
ASIC: TH1
Branch: master

Link is configured with 100G and the DAC cable is connected back to back with the ports in the same switch. No platform specific drivers are loaded apart from ASIC configuration files in 'device' directory.

Here are the logs from problematic image (May 20th Jenkins image)

Trial 1

100G DAC Cable connected to port 0 and port 1 after the box is rebooted.

root@sonic:/home/admin# show interfaces status
  Interface            Lanes    Speed    MTU            Alias    Vlan    Oper    Admin    Type    Asym PFC
-----------  ---------------  -------  -----  ---------------  ------  ------  -------  ------  ----------
  Ethernet0      49,50,51,52     100G   9100   hundredGigE1/1  routed      up       up     N/A         N/A
  Ethernet4      53,54,55,56     100G   9100   hundredGigE1/2  routed      up       up     N/A         N/A
  Ethernet8      57,58,59,60     100G   9100   hundredGigE1/3  routed    down       up     N/A         N/A
  ....

BCMCMD also shows link up in bcm asic for these 2 ports
root@sonic:/home/admin# bcmcmd ps | grep ce12
      ce12( 50)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No
root@sonic:/home/admin# bcmcmd ps | grep ce13
      ce13( 54)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No

Also "carrier" parameter is updated in "sys" directory for the ports connected with cables

root@sonic:/home/admin# cat /sys/class/net/Ethernet4/carrier
1
root@sonic:/home/admin# cat /sys/class/net/Ethernet0/carrier
1

Trial 2

100G DAC Cable connected to port 0 and connected to port 31.

root@sonic:/home/admin# show interfaces status
  Interface            Lanes    Speed    MTU            Alias    Vlan    Oper    Admin    Type    Asym PFC
-----------  ---------------  -------  -----  ---------------  ------  ------  -------  ------  ----------
  Ethernet0      49,50,51,52     100G   9100   hundredGigE1/1  routed      up       up     N/A         N/A
  Ethernet4      53,54,55,56     100G   9100   hundredGigE1/2  routed      up       up     N/A         N/A
  ...
  Ethernet120       9,10,11,12     100G   9100  hundredGigE1/31  routed    down       up     N/A         N/A
  Ethernet124      13,14,15,16     100G   9100  hundredGigE1/32  routed    down       up     N/A         N/A

BCMCMD also shows link up in bcm asic for these 2 ports

root@sonic:/home/admin# bcmcmd ps | grep ce12
      ce12( 50)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No
root@sonic:/home/admin# bcmcmd ps | grep ce3
       ce3( 13)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No

"carrier" parameter is not updated in "sys" directory for the ports connected with cables, still showing carrier up for port 1

root@sonic:/home/admin# cat /sys/class/net/Ethernet124/carrier
0
root@sonic:/home/admin# cat /sys/class/net/Ethernet4/carrier
1

Here is the dump from problematic image:

sonic_dump_sonic_20200526_071154.tar.gz

Last working commit from master branch: 1ef7403

Here are the logs from the working kernel image:

Trial 1

DAC cable is connected between physical port-0 & port-1 and system is rebooted.

root@sonic:/home/admin# show interfaces status
  Interface            Lanes    Speed    MTU            Alias    Vlan    Oper    Admin    Type    Asym PFC
-----------  ---------------  -------  -----  ---------------  ------  ------  -------  ------  ----------
  Ethernet0      49,50,51,52     100G   9100   hundredGigE1/1  routed      up       up     N/A         N/A
  Ethernet4      53,54,55,56     100G   9100   hundredGigE1/2  routed      up       up     N/A         N/A
 
root@sonic:/home/admin# bcmcmd ps | grep ce12
      ce12( 50)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No
root@sonic:/home/admin# bcmcmd ps | grep ce13
      ce13( 54)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No

root@sonic:/home/admin# cat /sys/class/net/Ethernet4/carrier
1
root@sonic:/home/admin# cat /sys/class/net/Ethernet0/carrier
1

Trial 2

100G DAC Cable connected to port 0 and connected to port 31.

root@sonic:/home/admin# show interfaces status
  Interface            Lanes    Speed    MTU            Alias    Vlan    Oper    Admin    Type    Asym PFC
-----------  ---------------  -------  -----  ---------------  ------  ------  -------  ------  ----------
  Ethernet0      49,50,51,52     100G   9100   hundredGigE1/1  routed      up       up     N/A         N/A
  Ethernet4      53,54,55,56     100G   9100   hundredGigE1/2  routed    down       up     N/A         N/A
  .....
  Ethernet120    9,10,11,12      100G   9100  hundredGigE1/31  routed    down       up     N/A         N/A
  Ethernet124    13,14,15,16     100G   9100  hundredGigE1/32  routed      up       up     N/A         N/A
  
root@sonic:/home/admin# bcmcmd ps | grep ce13
      ce13( 54)  down   4  100G  FD   SW  No   Forward          None    F    KR4  9122    No
	  
root@sonic:/home/admin# bcmcmd ps | grep ce12
      ce12( 50)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No
	  
root@sonic:/home/admin# bcmcmd ps | grep ce3
       ce3( 13)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No

root@sonic:/home/admin# cat /sys/class/net/Ethernet124/carrier
1
root@sonic:/home/admin# cat /sys/class/net/Ethernet0/carrier
1

Here is the dump from working image:

sonic_dump_sonic_20200522_143911.tar.gz

[ciju-juniper]

@lguohan @jleveque Please have a look and let me know how to proceed further. We are trying on 201911 branch as well. Will update the test results shortly.

[ciju-juniper]

In 201911 branch, issue is not seen.

[rlhui]

@ciju-juniper, it's a little bit not clear what the issue is still. Please make it more clear what is not expected, and make the formatting more clear. Thanks.

[ciju-juniper]

@rlhui When the cables are connected/removed in the switch ports, the link status is not updated in the kernel. The files '/sys/class/net/Ethernet*/carrier' are not updated whenever the OIR is done. Due to this problem, 'show interfaces status' is not reflecting the link status.

[lguohan]

@ciju-juniper , can you provide the dump file after you did trail 2 for the bad image. I need to look at the sairedis log to see if port status notification is generated or not. In your current dump, it seems it is for trail 1.

as you can see, it only has up notification. when you unplug Ethernet4, we should receive a port down notification from SAI, which I cannot find in the sairedis log.

lgh@gulv-vm3:~/sonic_dump_sonic_20200526_071154/log$ grep OPER_STATUS sairedis.rec 
2020-05-26.06:53:11.592558|n|port_state_change|[{"port_id":"oid:0x100000000000e","port_state":"SAI_PORT_OPER_STATUS_UP"}]|
2020-05-26.06:53:11.592925|s|SAI_OBJECT_TYPE_HOSTIF:oid:0xd0000000005ee|SAI_HOSTIF_ATTR_OPER_STATUS=true
2020-05-26.06:53:11.595581|n|port_state_change|[{"port_id":"oid:0x100000000000f","port_state":"SAI_PORT_OPER_STATUS_UP"}]|
2020-05-26.06:53:11.595802|s|SAI_OBJECT_TYPE_HOSTIF:oid:0xd0000000005ef|SAI_HOSTIF_ATTR_OPER_STATUS=true

[ciju-juniper]

@lguohan The dump was captured after Trial-2. As you can see '/sys/class/net/Ethernet4/carrier' still reports '1' even after the cable pull out.

We can try recreating the problem and capture the dump again. Needs a day or two as we don't have physical access to the box these days.

Could you tell me which driver in the kernel find out the link status change and update the '/sys/class/net/Ethernet4/carrier'?

[lguohan]

the mismatch here is that if you look at the broadcom.ps file, it says ce12 and ce13 up. In the trail-2, i think it should be ce3 to be up according to your good trail log. So, it seems after you swap the cable, ce3 is not up from broadcom.ps file.

that is why I am not sure if you have provide the right capture after trail-2.

      ce12( 50)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No      
      xe36( 51)  !ena   1   25G  FD None  No   Disable          None   FA  XGMII  9412    No      
      xe37( 52)  !ena   1   25G  FD None  No   Disable          None   FA  XGMII  9412    No      
      xe38( 53)  !ena   1   25G  FD None  No   Disable          None   FA  XGMII  9412    No      
      ce13( 54)  up     4  100G  FD   SW  No   Forward          None    F    KR4  9122    No      

ethernet4 is the broadcom knet driver. when there is link down, sai will send a notification to orchagent, and orchagent will call another SAI api to set the carrier down. From your log, i do not see the sai send the notification.

[ciju-juniper]

@lguohan Please see the attached test logs and the dump from the bad image.
Test_logs_28_05_2020.txt
sonic_dump_sonic_20200528_055104.tar.gz

[ciju-juniper]

@lguohan Look like there are no SAI notifications after Trial-2

crajank-mbp:log crajank$ grep -i "SAI_PORT_OPER_STATUS_" sairedis.rec 
2020-05-28.05:38:10.297727|n|port_state_change|[{"port_id":"oid:0x100000000000e","port_state":"SAI_PORT_OPER_STATUS_UP"}]|
2020-05-28.05:38:10.300046|n|port_state_change|[{"port_id":"oid:0x100000000000f","port_state":"SAI_PORT_OPER_STATUS_UP"}]|
2020-05-28.05:40:23.912578|n|port_state_change|[{"port_id":"oid:0x100000000000e","port_state":"SAI_PORT_OPER_STATUS_DOWN"}]|
2020-05-28.05:40:23.914670|n|port_state_change|[{"port_id":"oid:0x100000000000f","port_state":"SAI_PORT_OPER_STATUS_DOWN"}]|
2020-05-28.05:40:28.943032|n|port_state_change|[{"port_id":"oid:0x1000000000005","port_state":"SAI_PORT_OPER_STATUS_UP"}]|
2020-05-28.05:40:28.945893|n|port_state_change|[{"port_id":"oid:0x100000000000e","port_state":"SAI_PORT_OPER_STATUS_UP"}]|

[lguohan]

so, it looks like a broadcom SAI issue. if you bring down the port on the other side, will the SAI generate the notification?

[ciju-juniper]

@lguohan We had tested by connecting DAC cables in loopback within the same box.

Are you asking to do an 'ifconfig Ethernet0 down' in this loopback setup? Or connect the cables between two boxes and check?

[lguohan]

basically, I am asking to simulate the port oper status down and check if sai sends a notification to upper layer or not.

[BaluAlluru]

We tried to simulate the port oper status down by executing below command to make the port 1 down
bcmcmd "port ce13 Enable=False".

We are seeing the issue in latest SONIC image. Attached is jenkins290_logs file. This file has the logs captured for latest SONIC Jenkins 290 image on the box. In the attached log, the issue is seen after Trial 5. SAI is not sending notification to upper layer after few iterations.
Repeated multiple times the same exercise of disabling the port and enabling the port
and checking the SAI REDIS logs. Port State change event logs are not seen in SAI REDIS.

We also loaded "201911" release image on the box and repeated the same exercise. We don't see issue with this image. In this image, we see SAI sends notification to upper layer. we did many iterations of simulating the link status up/down and didn't observe the issue.
201911_logs attached file has logs for reference.

201911_logs.txt
jenkins290_logs.txt

[ciju-juniper]

@lguohan What could be the next steps to debug this issue further?

[ciju-juniper]

@lguohan How do we take this issue forward? Could we talk to BRCM to see what is going wrong with SAI?