Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

IO errors seen during warm reboot causing drop in traffic from servers #6240

Closed
vaibhavhd opened this issue Dec 17, 2020 · 8 comments
Closed

IO errors seen during warm reboot causing drop in traffic from servers #6240

vaibhavhd opened this issue Dec 17, 2020 · 8 comments
Assignees
@vaibhavhd
Labels
Issue for 202012 Master Branch Quality P0 Priority of the issue warmboot 👢

Comments

@vaibhavhd
Copy link
Contributor

Description

I/O tests during warm-reboot are failing due to server->t1 traffic being dropped.

Steps to reproduce the issue:

  1. Run test_advanced_reboot::test_warm_reboot on the latest Master image with SAI fix for Syncd APPLY_VIEW failure causes Orchagent crash after warm reboot #6069
  2. The test fails when traffic from servers is not received on the DUT.

In syslog, continous SAI_API_FDB:_brcm_sai_fdb_event_cb events are seen for a DUT port that is selected for the testing.
This is tested on DX010 T0 and issue is almost consistent across warm-reboots as long as traffic is running.

Additionally, this issue is not seen on a KVM device

Describe the results you received:

Dec 17 03:35:52.168652 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x26 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.168652 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x6a lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.168652 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x6a lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.168740 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x9 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.169648 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x9 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.169648 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x1 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.169648 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x1 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.169648 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x22 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.170482 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x22 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.170771 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x3a lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.171074 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x3a lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false
Dec 17 03:35:52.171074 str-dx010-acs-4 INFO syncd#syncd: [0] SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 1 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x26 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false

This is repetitive in the logs. For example the below grep counts:

grep -c "SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A vid:0x3e8, port:0x54 lagid:0x0 flags:0x1f0440 flags2:0x0 lag:false" ./syslog
77

$ grep -c "SAI_API_FDB:_brcm_sai_fdb_event_cb:58 FDB event: 0 for mac 00-06-07-08-09-0A" ./syslog
555

The test itself fails due to no packets received from servers. Below is a snippet from IO test running on PTF:

2020-12-17 09:10:47 : Send     1 Received     1 arp ping
2020-12-17 09:10:49 : Send   100 Received     0 servers->t1
2020-12-17 09:10:50 : Send   500 Received   500 t1->servers
2020-12-17 09:10:51 : Send    10 Received    10 ping DUT

The interface counters show drops seen on a DUT port:

root@str-dx010-acs-4:/var/log# show interfaces counters 
Last cached time was 2020-12-17 09:04:09.156657
      IFACE    STATE    RX_OK       RX_BPS    RX_UTIL    RX_ERR    RX_DRP    RX_OVR    TX_OK       TX_BPS    TX_UTIL    TX_ERR    TX_DRP    TX_OVR
-----------  -------  -------  -----------  ---------  --------  --------  --------  -------  -----------  ---------  --------  --------  --------
  Ethernet0        X        0     0.00 B/s      0.00%         0         0         0        0     0.00 B/s      0.00%         0         0         0
  Ethernet4        U       64    10.52 B/s      0.00%         0        20         0   10,306  1511.75 B/s      0.00%         0         0         0
  Ethernet8        U       96    14.92 B/s      0.00%         0        20         0   10,274  1506.49 B/s      0.00%         0         0         0
Ethernet12        U       90    14.18 B/s      0.00%         0        21         0   10,312  1515.24 B/s      0.00%         0         0         0
Ethernet16        U      109    16.79 B/s      0.00%         0        21         0   10,295  1512.90 B/s      0.00%         0         0         0
Ethernet20        U       92    14.45 B/s      0.00%         0        21         0   10,312  1515.24 B/s      0.00%         0         0         0
Ethernet24        U    5,300  1177.45 B/s      0.00%         0     5,221         0   10,794  1579.88 B/s      0.00%         0         0         0
Ethernet28        U       93    14.59 B/s      0.00%         0        21         0   10,293  1510.82 B/s      0.00%         0         0         0
Ethernet32        U       94    14.73 B/s      0.00%         0        21         0   10,291  1510.55 B/s      0.00%         0         0         0
Ethernet36        U       88    13.90 B/s      0.00%         0        21         0   10,281  1508.34 B/s      0.00%         0         0         0
Ethernet40        U      140    21.05 B/s      0.00%         0        21         0   10,255  1503.82 B/s      0.00%         0         0         0
Ethernet44        U       92    14.45 B/s      0.00%         0        21         0   10,272  1506.19 B/s      0.00%         0         0         0
Ethernet48        U       73    11.84 B/s      0.00%         0        21         0   10,284  1507.67 B/s      0.00%         0         0         0
Ethernet52        U       93    14.59 B/s      0.00%         0        21         0   10,244  1500.71 B/s      0.00%         0         0         0
Ethernet56        U      149    22.29 B/s      0.00%         0        21         0   10,182  1487.80 B/s      0.00%         0         0         0
Ethernet60        U      110    16.93 B/s      0.00%         0        21         0   10,139  1478.45 B/s      0.00%         0         0         0
Ethernet64        U       81    12.94 B/s      0.00%         0        21         0   10,173  1483.21 B/s      0.00%         0         0         0
Ethernet68        U      115    17.62 B/s      0.00%         0        21         0   10,146  1480.88 B/s      0.00%         0         0         0
Ethernet72        U       91    14.32 B/s      0.00%         0        21         0   10,187  1487.80 B/s      0.00%         0         0         0
Ethernet76        U       95    14.87 B/s      0.00%         0        21         0   10,155  1481.43 B/s      0.00%         0         0         0
Ethernet80        U       87    13.77 B/s      0.00%         0        21         0   10,191  1487.84 B/s      0.00%         0         0         0
Ethernet84        U      113    17.34 B/s      0.00%         0        21         0   10,095  1468.28 B/s      0.00%         0         0         0
Ethernet88        U      116    17.75 B/s      0.00%         0        21         0   10,066  1463.34 B/s      0.00%         0         0         0
Ethernet92        U       92    14.37 B/s      0.00%         0        20         0   10,103  1469.63 B/s      0.00%         0         0         0
Ethernet96        U       68    11.07 B/s      0.00%         0        20         0   10,145  1475.84 B/s      0.00%         0         0         0
Ethernet100        X        0     0.00 B/s      0.00%         0         0         0        0     0.00 B/s      0.00%         0         0         0
Ethernet104        X        0     0.00 B/s      0.00%         0         0         0        0     0.00 B/s      0.00%         0         0         0
Ethernet108        X        0     0.00 B/s      0.00%         0         0         0        0     0.00 B/s      0.00%         0         0         0
Ethernet112        U   10,332  2292.46 B/s      0.00%         0         0         0      921   206.61 B/s      0.00%         0         0         0
Ethernet116        U    5,026  1106.78 B/s      0.00%         0         0         0      900   200.71 B/s      0.00%         0         0         0
Ethernet120        U    2,840   618.34 B/s      0.00%         0         0         0      873   193.28 B/s      0.00%         0         0         0
Ethernet124        U   10,431  2314.59 B/s      0.00%         0         0         0      878   194.81 B/s      0.00%         0         0         0

Describe the results you expected:

Warm reboot test should pass with I/O passing for both traffic from servers and T1 devices.

Additional information you deem important (e.g. issue happens only occasionally):

The test used a patch for #6069 to unblock OA crash issue.

**Output of `show version`:**

```
(paste your output here)
```

**Attach debug file `sudo generate_dump`:**

```
(paste your output here)
```
@vaibhavhd
Copy link
Contributor Author

Looking more into the logs:
There is a flood of FDB events. MAC address 00-06-07-08-09-0A (used by PTF testutils) is continuously jumping to ALL the ports and gets cycled between AGED (event 0) and LEARNED (event 1). I am guessing that these events are based on SAI's enum values https://github.com/opencomputeproject/SAI/blob/master/inc/saifdb.h#L79

root@str-s6100-acs-4:~# for i in {1..50};
> do show mac | grep "08:09";
> done

   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet27  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet23  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet41  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet41  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet36  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet12  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet24  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet7   Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet52  Dynamic
   13    1000  00:06:07:08:09:0A  Ethernet40  Dynamic

@vaibhavhd
Copy link
Contributor Author

Side question - for all the traffic that is dropped, both RX_OK and RX_DRP counters are increased simultaneously. Aren't they both contrary in functionality - if DRP is seen, OK should not be increased, and vice-versa?

@vaibhavhd
Copy link
Contributor Author

This issue is seen only after DUT is warm rebooted and traffic from servers to T1 is dropped. Not seen on KVM or cold-rebooted DUT.

It is also hard to nail when the issue started occurring first, as the older versions of BRCM SAI in master had syncd crashes.

Looking at the syslog, there are SEVERAL errors seen during syncd warm reboot. Specifically the errors regarding VID to RID translation and why do we skip warm reboot for some attributes like SAI_SWITCH_ATTR_SRC_MAC_ADDRESS?

Dec 21 20:04:49.163536 str-s6100-acs-4 INFO syncd#syncd: [0] SAI_API_UNSPECIFIED:sai_api_initialize:371 BRCM SAI ver: [4.2.1.5], OCP SAI ver: [1.7.1], SDK ver: [sdk-6.5.19]
Dec 21 20:04:49.164052 str-s6100-acs-4 ERR syncd#syncd: [0] SAI_API_UNSPECIFIED:sai_api_query:420 Invalid sai_api_t 45 passed to sai_api_query
Dec 21 20:04:49.165584 str-s6100-acs-4 NOTICE syncd#syncd: :- sai_metadata_apis_query: :- failed to query api SAI_API_BMTOR: SAI_STATUS_INVALID_PARAMETER (-5)
Dec 21 20:04:49.165584 str-s6100-acs-4 NOTICE syncd#syncd: :- sai_metadata_apis_query: :- failed to query api SAI_API_MACSEC: SAI_STATUS_NOT_IMPLEMENTED (-15)
Dec 21 20:04:49.165584 str-s6100-acs-4 NOTICE syncd#syncd: :- initialize: sai_api_query failed for 2 apis
Dec 21 20:04:49.165584 str-s6100-acs-4 NOTICE syncd#syncd: :- Syncd: syncd started
Dec 21 20:04:49.173080 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestart: switches defined in warm restat: 1
Dec 21 20:04:49.173307 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch: switch oid:0x21000000000000
Dec 21 20:04:49.173379 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_LAG_DEFAULT_HASH_SEED:0
Dec 21 20:04:49.173620 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_FDB_AGING_TIME:0
Dec 21 20:04:49.173620 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_ECMP_DEFAULT_HASH_SEED:0
Dec 21 20:04:49.173620 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_INIT_SWITCH:true
Dec 21 20:04:49.173620 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_FDB_EVENT_NOTIFY:0x5651ddc50720
Dec 21 20:04:49.173657 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_PORT_STATE_CHANGE_NOTIFY:0x5651ddc50730
Dec 21 20:04:49.173657 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_SWITCH_SHUTDOWN_REQUEST_NOTIFY:0x5651ddc50740
Dec 21 20:04:49.173693 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch:  - attr: SAI_SWITCH_ATTR_SRC_MAC_ADDRESS:34:17:EB:49:61:00
Dec 21 20:04:49.174483 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch: skiping warm boot: SAI_SWITCH_ATTR_LAG_DEFAULT_HASH_SEED
Dec 21 20:04:49.174483 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch: skiping warm boot: SAI_SWITCH_ATTR_FDB_AGING_TIME
Dec 21 20:04:49.174483 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch: skiping warm boot: SAI_SWITCH_ATTR_ECMP_DEFAULT_HASH_SEED
Dec 21 20:04:49.174483 str-s6100-acs-4 NOTICE syncd#syncd: :- performWarmRestartSingleSwitch: skiping warm boot: SAI_SWITCH_ATTR_SRC_MAC_ADDRESS

Dec 21 20:05:01.249648 str-s6100-acs-4 ERR syncd#syncd: [0] SAI_API_SWITCH:sai_query_attribute_enum_values_capability:311 Error in enum capability query for obj type 
Dec 21 20:05:01.258443 str-s6100-acs-4 ERR syncd#syncd: [0] SAI_API_SWITCH:sai_object_type_get_availability:607 Error in available get for obj type 85

Dec 21 20:05:01.348236 str-s6100-acs-4 ERR syncd#syncd: message repeated 2 times: [ [0] SAI_API_SWITCH:sai_object_type_get_availability:607 Error in available get for obj type 85]
Dec 21 20:05:01.348236 str-s6100-acs-4 ERR syncd#syncd: [0] SAI_API_SWITCH:brcm_sai_get_switch_attribute:4643 acl table get max supported actions failed with error -327680.
Dec 21 20:05:19.453451 str-s6100-acs-4 ERR syncd#syncd: :- translateVidToRid: unable to get RID for VID oid:0x18000000000ea4
Dec 21 20:05:19.453901 str-s6100-acs-4 WARNING syncd#syncd: :- processClearStatsEvent: VID to RID translation failure: SAI_OBJECT_TYPE_BUFFER_POOL:oid:0x18000000000ea4
Dec 21 20:05:19.493487 str-s6100-acs-4 WARNING syncd#syncd: :- processClearStatsEvent: VID to RID translation failure: SAI_OBJECT_TYPE_BUFFER_POOL:oid:0x18000000000ea5
Dec 21 20:05:19.514399 str-s6100-acs-4 WARNING syncd#syncd: :- processClearStatsEvent: VID to RID translation failure: SAI_OBJECT_TYPE_BUFFER_POOL:oid:0x18000000000ea6

@vaibhavhd
Copy link
Contributor Author

Now this is being tested and seen on latest SAI version and master image:

BRCM SAI ver: [4.2.1.5], OCP SAI ver: [1.7.1], SDK ver: [sdk-6.5.19]

admin@str-s6100-acs-4:~$ show ver

SONiC Software Version: SONiC.HEAD.163-ee8c3d34
Distribution: Debian 10.7
Kernel: 4.19.0-9-2-amd64
Build commit: ee8c3d34
Build date: Mon Dec 21 07:35:11 UTC 2020

@vaibhavhd
Copy link
Contributor Author

With every traffic drop, RDROP counters are increasing. This is suspected to be MMU handling/config related post warm-reboot.

root@str-s6100-acs-4:/var/log# bcmcmd "cstat xe30"
cstat xe30

+------------------Programmable Statistics Counters[Port xe30]------------------+
| Type | No. |       Value       |                Enabled For                   |
+-------------------------------------------------------------------------------+
|  RX  | 0(R)|              66300| RIPD4 RIPD6 RDISC RPORTD                     |
|      |     |                   | PDISC RDROP VLANDR                           |
|      | 7   |              55000| RDROP                                        |
+-------------------------------------------------------------------------------+
|      | 4(R)|              10221| TGIP4 TGIP6                                  |
|      | 6   |              10221| TGIP4                                        |
+-------------------------------------------------------------------------------+

drivshell>
root@str-s6100-acs-4:/var/log# bcmcmd "cstat xe30"
cstat xe30

+------------------Programmable Statistics Counters[Port xe30]------------------+
| Type | No. |       Value       |                Enabled For                   |
+-------------------------------------------------------------------------------+
|  RX  | 0(R)|              66400| RIPD4 RIPD6 RDISC RPORTD                     |
|      |     |                   | PDISC RDROP VLANDR                           |
|      | 7   |              55100| RDROP                                        |
+-------------------------------------------------------------------------------+
|      | 4(R)|              10235| TGIP4 TGIP6                                  |
|      | 6   |              10235| TGIP4                                        |
+-------------------------------------------------------------------------------+
drivshell>
root@str-s6100-acs-4:/var/log#

Output of my station tcam is slightly different after COLD reboot and WARM reboot.
In the case of warm-reboot, there is an extra "EVEN_PARITY=1" on all entries.

Looping in BRCM team to look further into the issue.

@vaibhavhd
Copy link
Contributor Author

Thanks @gechiang for the debug help and creating a BRCM SAI CSP for this - CS00011676762.

@vaibhavhd vaibhavhd added the P0 Priority of the issue label Dec 23, 2020
@daall daall mentioned this issue Dec 23, 2020
Closed
@kcudnik
Copy link
Contributor

kcudnik commented Jan 5, 2021 •
edited
Loading

Fix here: sonic-net/sonic-sairedis#761, for issue with bulk set operation, when traffic was blackholled, next hop for default route was set to 0x0, since overridden by last attribute which was a bug
but there still maybe some other ip2me related issues in brcm sai side

@vaibhavhd
Copy link
Contributor Author

This issue is fixed by sonic-net/sonic-sairedis#761

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@vaibhavhd vaibhavhd

Labels
Issue for 202012 Master Branch Quality P0 Priority of the issue warmboot 👢
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kcudnik @yxieca @vaibhavhd