avoid exception when local-chassis information is missing #12

taoyl-ms · 2018-09-26T00:36:43Z

We are seeing the following exception that causes lldp-syncd to stop proper functioning.

Sep 25 18:58:24.741727 sonic-7 INFO lldp#lldp-syncd [lldp_syncd] INFO: Starting SONiC LLDP sync daemon...
Sep 25 18:58:24.747158 sonic-7 INFO lldp#lldp-syncd [lldp_syncd] INFO: [lldp dbsyncd] Connected to configdb
Sep 25 18:58:24.807744 sonic-7 INFO lldp#supervisord: lldp-syncd Exception in thread LldpSyncDaemon:
Sep 25 18:58:24.807994 sonic-7 INFO lldp#supervisord: lldp-syncd Traceback (most recent call last):
Sep 25 18:58:24.808174 sonic-7 INFO lldp#supervisord: lldp-syncd   File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
Sep 25 18:58:24.808443 sonic-7 INFO lldp#supervisord: lldp-syncd     self.run()
Sep 25 18:58:24.808602 sonic-7 INFO lldp#supervisord: lldp-syncd   File "/usr/local/lib/python2.7/dist-packages/sonic_syncd/interface.py", line 47, in run
Sep 25 18:58:24.808763 sonic-7 INFO lldp#supervisord: lldp-syncd     self.sync(parsed_update)
Sep 25 18:58:24.808929 sonic-7 INFO lldp#supervisord: lldp-syncd   File "/usr/local/lib/python2.7/dist-packages/lldp_syncd/daemon.py", line 344, in sync
Sep 25 18:58:24.809200 sonic-7 INFO lldp#supervisord: lldp-syncd     chassis_update = parsed_update.pop('local-chassis')
Sep 25 18:58:24.809502 sonic-7 INFO lldp#supervisord: lldp-syncd KeyError: 'local-chassis'

This PR will fix this bug. However, we should continue to dig deeper why local-chassis key is missing from parsed_update.

lguohan · 2018-09-26T07:58:19Z

what i can see is that if the lldpd is not started then we can get such output. could this be the case?

in case of root causing the issue, i would suggest to instrumenting scrap_output function so that we know what the output is from lldpcli.

root@str-s6000-on-4:/# lldpcli -f json show chassis
2018-09-26T07:36:54 [WARN/control] unable to connect to socket /var/run/lldpd.socket: No such file or directory
{
  "local-chassis": {
    "chassis": {
      "id": {
        "type": "",
        "value": ""
      },
      "capability": [
        {
          "type": "Other",
          "enabled": true
        },
        {
          "type": "Wlan",
          "enabled": true
        }
      ]
    }
  }
}

taoyl-ms · 2018-09-26T20:37:46Z

As you showed, even if lldpd is not running, lldpcli will give an empty json response and the key shouldn't be missing there. I do agree we need to add some instrumenting to root cause it.

…u's. Problem is observed when directly connecting a Cisco's UCS server with a sonic device through a Cisco's 10G VIC network-interface. These NICs make use of hardware capabilities to generate/process lldp pdu's. Problem is seen in sonic side when the cisco-box advertises lldp pdu's carrying "Data Center Bridging Capability Exchange protocol" extensions (DCBX). Even though sonic's lldpd process seems to be correctly parsing the pdu headers, this one is incapable of parsing the DCBX extensions. This factor seems to be playing a role in the way in which lldpctl/cli tool exposes ldp state to lldp-syncd. This patch simply adds basic logic to discard incoming chassis-TLV attributes that are not formatted as expected by the current lldp-syncd code, which is the ultimate cause behind these logs being generated by lldp-syncd (below). A more complete solution would involve changes in lldpd and/or lldpctl code to fully support DCBX extensions. Apr 21 05:34:21.269898 lnos-x1-a-asw02 ERR lldp-syncd [lldp_syncd] ERROR: Could not infer system information from: {u'id': {u'type': u'mac', u'value': u'04:62:73:f7:e5:c6'}, u'ttl': u'120'}#012Traceback (most recent call last):sonic-net#12 File "/usr/local/lib/python2.7/dist-packages/lldp_syncd/daemon.py", line 196, in parse_chassis#012 (rem_name, rem_attributes), = chassis_attributes.items()#012ValueError: too many values to unpack <-- lldpd's parsing process seems to be correct for both the regular and dcbx pdu's: ------------------------------------------------------------------------------- Interface: Ethernet16, via: LLDP, RID: 1, Time: 0 day, 00:00:55 Chassis: ChassisID: mac 04:62:73:f7:e5:c6 TTL: 120 Port: PortID: mac 04:62:73:f7:e5:ce Unknown TLVs: TLV: OUI: 00,01,42, SubType: 1, Len: 1 01 <==== DCBX TLVs!!!!!!! ------------------------------------------------------------------------------- Interface: Ethernet16, via: LLDP, RID: 5, Time: 0 day, 00:00:25 Chassis: ChassisID: mac fe:54:00:d1:e0:7b SysName: server06 SysDescr: Ubuntu 16.04.2 LTS Linux 4.4.0-77-generic #98-Ubuntu SMP Wed Apr 26 08:34:02 UTC 2017 x86_64 TTL: 120 MgmtIP: 172.25.11.16 MgmtIP: fc00:99:99::99 Capability: Bridge, on Capability: Router, on Capability: Wlan, off Capability: Station, off Port: PortID: mac 04:62:73:f7:e5:d3 PortDescr: eth1 ------------------------------------------------------------------------------- <-- Regular LDP PDU as it arrives at sonic dut (main tlvs only): 01:46:02.619478 LLDP, length 202 Chassis ID TLV (1), length 7 Subtype MAC address (4): fe:54:00:d1:e0:7b (oui Unknown) 0x0000: 04fe 5400 d1e0 7b Port ID TLV (2), length 7 Subtype MAC address (3): 04:62:73:f7:e5:d3 (oui Unknown) 0x0000: 0304 6273 f7e5 d3 Time to Live TLV (3), length 2: TTL 120s 0x0000: 0078 System Name TLV (5), length 8: server06 0x0000: 7365 7276 6572 3036 System Description TLV (6), length 92 <-- LDP PDU with DCBX extensions as it arrives at sonic dut (main tlvs only) 01:45:48.360547 LLDP, length 88 Chassis ID TLV (1), length 7 Subtype MAC address (4): 04:62:73:f7:e5:c6 (oui Unknown) 0x0000: 0404 6273 f7e5 c6 Port ID TLV (2), length 7 Subtype MAC address (3): 04:62:73:f7:e5:ce (oui Unknown) 0x0000: 0304 6273 f7e5 ce Time to Live TLV (3), length 2: TTL 120s 0x0000: 0078 Organization specific TLV (127), length 55: OUI DCBX (0x001b21) DCB Capability Exchange Protocol Rev 1.01 Subtype (2) Control - Protocol Control (type 0x1, length 10) <-- As mentioned above, even though lldp's seems to be parsing both pdu's correctly (excluding the dcbx tlv), lldpctl's exporting logic seems to be inconsistent in the 'working' and 'non-working' cases (see below). Notice that in the 'working' case there's a single element/key within the chassis-tlv (the name of the remote nbr: server06), whereas in the 'non-working' case we see two keys ('id' and 'ttl'). The existing lldp-syncd parser expects a single key within the chassis-tlv, so that's why i'm adjusting this logic to gracefully discard this tlv when the layout doesn't match the expectations. <-- Working case: { "Ethernet16": { "age": "0 day, 02:21:53", "via": "LLDP", "rid": "5", "chassis": { "server06": { "capability": [ { "type": "Bridge", "enabled": true }, { "type": "Router", "enabled": true }, { "type": "Wlan", "enabled": false }, { "type": "Station", "enabled": false } ], "id": { "value": "fe:54:00:d1:e0:7b", "type": "mac" }, "mgmt-ip": [ "172.25.11.16", "fc00:99:99::99" ], "ttl": "120", "descr": "Ubuntu 16.04.2 LTS Linux 4.4.0-77-generic #98-Ubuntu SMP Wed Apr 26 08:34:02 UTC 2017 x86_64" } }, "port": { "id": { "value": "04:62:73:f7:e5:d3", "type": "mac" }, "descr": "eth1" } } } <-- Non-working case: "Ethernet16": { "age": "0 day, 02:22:23", "via": "LLDP", "unknown-tlvs": { "unknown-tlv": { "oui": "00,01,42", "subtype": "1", "len": "1", "value": "01" } }, "rid": "1", "chassis": { "id": { "value": "04:62:73:f7:e5:c6", "type": "mac" }, "ttl": "120" }, "port": { "id": { "value": "04:62:73:f7:e5:ce", "type": "mac" } } } }, RB=1288687 G=lnos-reviewers R=ntrianta,pmao,rmolina,sfardeen,zxu A= Conflicts: src/lldp_syncd/daemon.py

#### Why I did lldpctl can sometimes return negative age i.e. Negative age is seen from lldpctl because of the hwclock of the system being forward in time and the system time is later reset to correct time by ntpd. But the lldp agent for eth0 can start before ntpd resets the system clock and thus the init time is forward in time. Thus for every 10 sec when the lldp_syncd polls the lldpd it returns negative age. ``` { "lldp": { "interface": { "eth0": { "via": "LLDP", "rid": "1", "age": "-2 day, -23:-59:-47", } } } ``` In those cases the lldp_syncd fails the parsing and throws error logs like these and also doesn't update APP_DB Table which is used by SNMP. ``` Jan 30 02:05:31.186000 r-r740-05-bf2-sonic-01 ERR lldp#lldp-syncd [lldp_syncd] ERROR: Failed to parse LLDPd JSON. #12{'lldp': {'interface': [{'eth0': {'via': 'LLDP', 'rid': '1', 'age': '-2 day, -23:-55:-15', 'chassis': {'MTR-F-1-S-LAB-R3-3-SW01': {'id': {'type': 'mac', 'value': 'e0:07:1b:38:37:c0'}, 'descr': 'HP J9775A 2530-48G Switch, revision YA.16.11.0003, ROM YA.15.20 (/ws/swbuildm/rel_beluru_qaoff/code/build/lakes(swbuildm_rel_beluru_qaoff_rel_beluru))', 'mgmt-ip': '10.210.100.142', 'capability': {'type': 'Bridge', 'enabled': True}}}, 'port': {'id': {'type': 'local', 'value': '14'}, 'descr': '14', 'ttl': '120', 'auto-negotiation': {'supported': True, 'enabled': True, 'advertised': [{'type': '10Base-T', 'hd': True, 'fd': True}, {'type': '100Base-TX', 'hd': True, 'fd': True}, {'type': '1000Base-T', 'hd': False, 'fd': True}], 'current': '1000BaseTFD - Four-pair Category 5 UTP, full duplex mode'}, 'power': {'supported': False, 'enabled': False, 'paircontrol': False, 'device-type': 'PSE', 'pairs': 'signal', 'class': 'class 0'}}, 'vlan': {'vlan-id': '23', 'pvid': True}, 'unknown-tlvs': {'unknown-tlv': {'oui': '00,16,B9', 'subtype': '2', 'len': '2', 'value': '00,01'}}}}, {'Ethernet0': {'via': 'LLDP', 'rid': '4', 'age': '0 day, 00:03:17', 'chassis': {'ARISTA01T0': {'id': {'type': 'mac', 'value': '22:25:8e:ab:b6:2e'}, 'descr': 'Arista Networks EOS version 4.27.0F-24308433.4270F (engineering build) running on an Arista cEOSLab', 'mgmt-ip': '10.215.11.41', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}]}}, 'port': {'id': {'type': 'ifname', 'value': 'Ethernet1'}, 'ttl': '120', 'mfs': '9236'}}}, {'Ethernet4': {'via': 'LLDP', 'rid': '3', 'age': '0 day, 00:03:17', 'chassis': {'ARISTA02T0': {'id': {'type': 'mac', 'value': '0e:b9:12:65:d3:30'}, 'descr': 'Arista Networks EOS version 4.27.0F-24308433.4270F (engineering build) running on an Arista cEOSLab', 'mgmt-ip': '10.215.11.42', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}]}}, 'port': {'id': {'type': 'ifname', 'value': 'Ethernet1'}, 'ttl': '120', 'mfs': '9236'}}}]}, 'lldp_loc_chassis': {'local-chassis': {'chassis': {'r-r740-05-bf2-sonic-01': {'id': {'type': 'mac', 'value': '08:c0:eb:7b:c0:ac'}, 'descr': 'SONiC Software Version: SONiC.bluefield.94-d9f9de047_Internal - HwSku: Nvidia-MBF2H536C - Distribution: Debian 11.6 - Kernel: 5.10.0-18-2-arm64', 'mgmt-ip': '10.215.11.59', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}, {'type': 'Wlan', 'enabled': False}, {'type': 'Station', 'enabled': False}]}}}}}#12 -- #012Traceback (most recent call last):#12 File "/usr/local/lib/python3.9/dist-packages/lldp_syncd/daemon.py", line 254, in parse_update#012 str(parse_time(if_attributes.get('age')))})#12 File "/usr/local/lib/python3.9/dist-packages/lldp_syncd/daemon.py", line 48, in parse_time#012 struct_time = time.strptime(hour_min_secs, LLDPD_TIME_FORMAT)#12 File "/usr/lib/python3.9/_strptime.py", line 562, in _strptime_time#012 tt = _strptime(data_string, format)[0]#12 File "/usr/lib/python3.9/_strptime.py", line 349, in _strptime#012 raise ValueError("time data %r does not match format %r" %#012ValueError: time data '-23:-55:-15' does not match format '%H:%M:%S' Jan 30 02:05:41.297868 r-r740-05-bf2-sonic-01 ERR lldp#lldp-syncd [lldp_syncd] ERROR: Failed to parse LLDPd JSON. #12{'lldp': {'interface': [{'eth0': {'via': 'LLDP', 'rid': '1', 'age': '-2 day, -23:-55:-5', 'chassis': {'MTR-F-1-S-LAB-R3-3-SW01': {'id': {'type': 'mac', 'value': 'e0:07:1b:38:37:c0'}, 'descr': 'HP J9775A 2530-48G Switch, revision YA.16.11.0003, ROM YA.15.20 (/ws/swbuildm/rel_beluru_qaoff/code/build/lakes(swbuildm_rel_beluru_qaoff_rel_beluru))', 'mgmt-ip': '10.210.100.142', 'capability': {'type': 'Bridge', 'enabled': True}}}, 'port': {'id': {'type': 'local', 'value': '14'}, 'descr': '14', 'ttl': '120', 'auto-negotiation': {'supported': True, 'enabled': True, 'advertised': [{'type': '10Base-T', 'hd': True, 'fd': True}, {'type': '100Base-TX', 'hd': True, 'fd': True}, {'type': '1000Base-T', 'hd': False, 'fd': True}], 'current': '1000BaseTFD - Four-pair Category 5 UTP, full duplex mode'}, 'power': {'supported': False, 'enabled': False, 'paircontrol': False, 'device-type': 'PSE', 'pairs': 'signal', 'class': 'class 0'}}, 'vlan': {'vlan-id': '23', 'pvid': True}, 'unknown-tlvs': {'unknown-tlv': {'oui': '00,16,B9', 'subtype': '2', 'len': '2', 'value': '00,01'}}}}, {'Ethernet0': {'via': 'LLDP', 'rid': '4', 'age': '0 day, 00:03:27', 'chassis': {'ARISTA01T0': {'id': {'type': 'mac', 'value': '22:25:8e:ab:b6:2e'}, 'descr': 'Arista Networks EOS version 4.27.0F-24308433.4270F (engineering build) running on an Arista cEOSLab', 'mgmt-ip': '10.215.11.41', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}]}}, 'port': {'id': {'type': 'ifname', 'value': 'Ethernet1'}, 'ttl': '120', 'mfs': '9236'}}}, {'Ethernet4': {'via': 'LLDP', 'rid': '3', 'age': '0 day, 00:03:27', 'chassis': {'ARISTA02T0': {'id': {'type': 'mac', 'value': '0e:b9:12:65:d3:30'}, 'descr': 'Arista Networks EOS version 4.27.0F-24308433.4270F (engineering build) running on an Arista cEOSLab', 'mgmt-ip': '10.215.11.42', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}]}}, 'port': {'id': {'type': 'ifname', 'value': 'Ethernet1'}, 'ttl': '120', 'mfs': '9236'}}}]}, 'lldp_loc_chassis': {'local-chassis': {'chassis': {'r-r740-05-bf2-sonic-01': {'id': {'type': 'mac', 'value': '08:c0:eb:7b:c0:ac'}, 'descr': 'SONiC Software Version: SONiC.bluefield.94-d9f9de047_Internal - HwSku: Nvidia-MBF2H536C - Distribution: Debian 11.6 - Kernel: 5.10.0-18-2-arm64', 'mgmt-ip': '10.215.11.59', 'capability': [{'type': 'Bridge', 'enabled': True}, {'type': 'Router', 'enabled': True}, {'type': 'Wlan', 'enabled': False}, {'type': 'Station', 'enabled': False}]}}}}}#12 -- #012Traceback (most recent call last):#12 File "/usr/local/lib/python3.9/dist-packages/lldp_syncd/daemon.py", line 254, in parse_update#012 str(parse_time(if_attributes.get('age')))})#12 File "/usr/local/lib/python3.9/dist-packages/lldp_syncd/daemon.py", line 48, in parse_time#012 struct_time = time.strptime(hour_min_secs, LLDPD_TIME_FORMAT)#12 File "/usr/lib/python3.9/_strptime.py", line 562, in _strptime_time#012 tt = _strptime(data_string, format)[0]#12 File "/usr/lib/python3.9/_strptime.py", line 349, in _strptime#012 raise ValueError("time data %r does not match format %r" %#012ValueError: time data '-23:-55:-5' does not match format '%H:%M:%S' ``` #### What I did Don't fail updating the APP_DB with the contents of lldp json when there is error is age field. when the hwclock of the system is set forward in time and t

avoid exception when local-chassis information is missing

370a572

taoyl-ms requested review from lguohan and yxieca September 26, 2018 00:36

yxieca approved these changes Sep 26, 2018

View reviewed changes

taoyl-ms added the bug label Sep 26, 2018

taoyl-ms merged commit 1cdcffc into sonic-net:master Sep 26, 2018

taoyl-ms mentioned this pull request Sep 28, 2018

Update dbsyncd submodule sonic-net/sonic-buildimage#2094

Merged

samKDas mentioned this pull request Feb 18, 2020

Exception in snmp Subagent in PTF32 topology #27

Open

vasant17 mentioned this pull request Sep 11, 2020

Negative LLDP time #29

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

avoid exception when local-chassis information is missing #12

avoid exception when local-chassis information is missing #12

taoyl-ms commented Sep 26, 2018

lguohan commented Sep 26, 2018

taoyl-ms commented Sep 26, 2018

avoid exception when local-chassis information is missing #12

avoid exception when local-chassis information is missing #12

Conversation

taoyl-ms commented Sep 26, 2018

lguohan commented Sep 26, 2018

taoyl-ms commented Sep 26, 2018