Skip to content

Handled the error case of negative age #57

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.

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

Merged
merged 1 commit into from
Mar 13, 2023

Conversation

vivekrnv
Copy link
Contributor

@vivekrnv vivekrnv commented Feb 8, 2023

Signed-off-by: Vivek Reddy [email protected]

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. #012{'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}]}}}}}#012 -- #012Traceback (most recent call last):#012  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')))})#012  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)#012  File "/usr/lib/python3.9/_strptime.py", line 562, in _strptime_time#012    tt = _strptime(data_string, format)[0]#012  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. #012{'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}]}}}}}#012 -- #012Traceback (most recent call last):#012  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')))})#012  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)#012  File "/usr/lib/python3.9/_strptime.py", line 562, in _strptime_time#012    tt = _strptime(data_string, format)[0]#012  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

@liat-grozovik
Copy link

@qiluo-msft @yxieca could you please help to review or assign someone?

@liat-grozovik
Copy link

@vivekrnv do we need this for 202211 as well?

@vivekrnv
Copy link
Contributor Author

@liat-grozovik, Yes. Can also be backported to 202205 (Not seen on this, but possible)

@liat-grozovik
Copy link

liat-grozovik commented Feb 26, 2023

@StormLiangMS can you please help to approve/merge? pls also add the label for 202211 and 202205?

@liat-grozovik
Copy link

@StormLiangMS can you please help to approve/merge? pls also add the label for 202211 and 202205?

@dgsudharsan
Copy link

@liat-grozovik There is no separate branch for 202211. We just need to update submodule in all relevant branches after this fix is merged.

@abdosi @qiluo-msft Can you please help to merge this? We will raise a submodule update in relevant branches

@qiluo-msft qiluo-msft merged commit fa8b709 into sonic-net:master Mar 13, 2023
@vivekrnv
Copy link
Contributor Author

@yxieca Can you backport this to 202205?

yxieca pushed a commit that referenced this pull request Mar 17, 2023
#### 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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants