[utils] adding HistoryTracker module (#6807)

This commit adds History Tracker feature and its CLI support. This
feature records history of different events as the Thread network
operates (e.g., history of RX and TX IPv6 messages or network info
changes).

Recorded entries are timestamped. When the history list is read, the
timestamps are given as the entry age relative to the time the list
is being read. For example in CLI a timestamp can be shown as
`02:31:50.628 ago` indicating the entry was recorded 2 hours, 31 min,
50 sec, and 628 msec ago. Number of days is added for events that are
older than 24 hours, e.g., `31 days 03:00:23.931 ago`. Timestamps use
millisecond accuracy and are tacked up to 49 days. If an event is
older than 49 days, the entry is still tracked in the list but the
timestamp is shown as old or `more than 49 days ago`.

The `HistoryTracker` currently maintains 3 lists. The Network Info
history tracks changes to Device Role, Mode, RLOC16 and Partition ID.
The RX/TX history list records information about the received/sent
IPv6 messages:
- Message type (UDP, TCP, ICMP6 (and its subtype), etc.)
- Source and destination IPv6 addresses and port numbers
- IPv6 payload length
- The message checksum (for UDP, TCP, or ICMP6).
- Whether or not the link-layer security was used
- Message priority: low, norm, high, net (for control messages)
- Short address (RLOC16) of neighbor who send/received the msg
- Received Signal Strength (in dBm) for RX only
- Radio link info (15.4/TREL) on which msg was sent/received
  (useful when `OPENTHREAD_CONFIG_MULTI_RADIO` is enabled)

Config `HISTORY_TRACKER_EXCLUDE_THREAD_CONTROL_MESSAGES` can be used
to configure `HistoryTracker` to exclude Thread Control message
(e.g., MLE, TMF) from TX and RX history.

The number of entries recorded for each history list is configurable
through a set of OpenThread config options, e.g., number of entries
in Network Info history list is specified by OpenThread config option
`OPENTHREAD_CONFIG_HISTORY_TRACKER_NET_INFO_LIST_SIZE`. The
`HistoryTracker` will keep the most recent entries overwriting oldest
ones when the list gets full.

This commit also adds support for `HistoryTracker` in CLI. The CLI
commands provide two style for printing the history information: A
table format (more human-readable) and list style (better suited for
parsing by machine/code). `README_HISTORY.md` is added to document
the commands and the info provided by each history list entry.

This commit also adds `test_history_tracker.py` test-case which
covers the behavior of `HistoryTracker`.
This commit is contained in:
Abtin Keshavarzian
2021-08-12 15:47:26 -07:00
committed by GitHub
parent 59f7a9aed6
commit 2798cc9c05
51 changed files with 2544 additions and 108 deletions
+2
View File
@@ -162,6 +162,7 @@ EXTRA_DIST = \
test_diag.py \
test_dns_client_config_auto_start.py \
test_dnssd.py \
test_history_tracker.py \
test_ipv6.py \
test_ipv6_fragmentation.py \
test_ipv6_source_selection.py \
@@ -228,6 +229,7 @@ check_SCRIPTS = \
test_diag.py \
test_dns_client_config_auto_start.py \
test_dnssd.py \
test_history_tracker.py \
test_ipv6.py \
test_ipv6_fragmentation.py \
test_ipv6_source_selection.py \
+110
View File
@@ -1331,6 +1331,10 @@ class NodeImpl:
self.send_command(cmd)
self._expect_done()
def get_partition_id(self):
self.send_command('partitionid')
return self._expect_result(r'\d+')
def get_preferred_partition_id(self):
self.send_command('partitionid preferred')
return self._expect_result(r'\d+')
@@ -2720,6 +2724,112 @@ class NodeImpl:
self.send_command(cmd)
self._expect_command_output(cmd)
def history_netinfo(self, num_entries=0):
"""
Get the `netinfo` history list, parse each entry and return
a list of dictionary (string key and string value) entries.
Example of return value:
[
{
'age': '00:00:00.000 ago',
'role': 'disabled',
'mode': 'rdn',
'rloc16': '0x7400',
'partition-id': '1318093703'
},
{
'age': '00:00:02.588 ago',
'role': 'leader',
'mode': 'rdn',
'rloc16': '0x7400',
'partition-id': '1318093703'
}
]
"""
cmd = f'history netinfo list {num_entries}'
self.send_command(cmd)
output = self._expect_command_output(cmd)
netinfos = []
for entry in output:
netinfo = {}
age, info = entry.split(' -> ')
netinfo['age'] = age
for item in info.split(' '):
k, v = item.split(':')
netinfo[k] = v
netinfos.append(netinfo)
return netinfos
def history_rx(self, num_entries=0):
"""
Get the IPv6 RX history list, parse each entry and return
a list of dictionary (string key and string value) entries.
Example of return value:
[
{
'age': '00:00:01.999',
'type': 'ICMP6(EchoReqst)',
'len': '16',
'sec': 'yes',
'prio': 'norm',
'rss': '-20',
'from': '0xac00',
'radio': '15.4',
'src': '[fd00:db8:0:0:2cfa:fd61:58a9:f0aa]:0',
'dst': '[fd00:db8:0:0:ed7e:2d04:e543:eba5]:0',
}
]
"""
cmd = f'history rx list {num_entries}'
self.send_command(cmd)
return self._parse_history_rx_tx_ouput(self._expect_command_output(cmd))
def history_tx(self, num_entries=0):
"""
Get the IPv6 TX history list, parse each entry and return
a list of dictionary (string key and string value) entries.
Example of return value:
[
{
'age': '00:00:01.999',
'type': 'ICMP6(EchoReply)',
'len': '16',
'sec': 'yes',
'prio': 'norm',
'to': '0xac00',
'tx-success': 'yes',
'radio': '15.4',
'src': '[fd00:db8:0:0:ed7e:2d04:e543:eba5]:0',
'dst': '[fd00:db8:0:0:2cfa:fd61:58a9:f0aa]:0',
}
]
"""
cmd = f'history tx list {num_entries}'
self.send_command(cmd)
return self._parse_history_rx_tx_ouput(self._expect_command_output(cmd))
def _parse_history_rx_tx_ouput(self, lines):
rxtx_list = []
for line in lines:
if line.strip().startswith('type:'):
for item in line.strip().split(' '):
k, v = item.split(':')
entry[k] = v
elif line.strip().startswith('src:'):
entry['src'] = line[4:]
elif line.strip().startswith('dst:'):
entry['dst'] = line[4:]
rxtx_list.append(entry)
else:
entry = {}
entry['age'] = line
return rxtx_list
class Node(NodeImpl, OtCli):
pass
+210
View File
@@ -0,0 +1,210 @@
#!/usr/bin/env python3
#
# Copyright (c) 2021, The OpenThread Authors.
# All rights reserved.
#
# Redistribution and use in source and binary forms, with or without
# modification, are permitted provided that the following conditions are met:
# 1. Redistributions of source code must retain the above copyright
# notice, this list of conditions and the following disclaimer.
# 2. Redistributions in binary form must reproduce the above copyright
# notice, this list of conditions and the following disclaimer in the
# documentation and/or other materials provided with the distribution.
# 3. Neither the name of the copyright holder nor the
# names of its contributors may be used to endorse or promote products
# derived from this software without specific prior written permission.
#
# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
# AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
# ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
# LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
# CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
# SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
# INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
# CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
# ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
# POSSIBILITY OF SUCH DAMAGE.
#
import os
import unittest
import sys
import thread_cert
# Test description:
# This test verifies History Tracker behavior.
#
# Topology:
#
# LEADER
# |
# |
# CHILD
#
LEADER = 1
CHILD = 2
SHORT_WAIT = 5
ONE_DAY = 24 * 60 * 60
MAX_AGE_IN_DAYS = 49
class TestHistoryTracker(thread_cert.TestCase):
USE_MESSAGE_FACTORY = False
SUPPORT_NCP = False
TOPOLOGY = {
LEADER: {
'name': 'Leader',
'mode': 'rdn',
},
CHILD: {
'name': 'Child',
'mode': 'n',
},
}
def test(self):
leader = self.nodes[LEADER]
child = self.nodes[CHILD]
# Start the leader and verify that 'netinfo' history
# is updated correctly.
leader.start()
self.simulator.go(SHORT_WAIT)
self.assertEqual(leader.get_state(), 'leader')
netinfo = leader.history_netinfo()
self.assertEqual(len(netinfo), 2)
self.assertEqual(netinfo[0]['role'], 'leader')
self.assertEqual(netinfo[0]['mode'], 'rdn')
self.assertEqual(int(netinfo[0]['rloc16'], 16), leader.get_addr16())
self.assertEqual(netinfo[0]['partition-id'], leader.get_partition_id())
self.assertEqual(netinfo[1]['role'], 'detached')
# Stop the leader
leader.thread_stop()
leader.interface_down()
self.simulator.go(SHORT_WAIT)
netinfo = leader.history_netinfo(2)
self.assertEqual(len(netinfo), 2)
self.assertEqual(netinfo[0]['role'], 'disabled')
self.assertEqual(netinfo[1]['role'], 'leader')
# Wait for one day, two days, then up to max age and verify that
# `netinfo` entry age is updated correctly.
#
# Since we want to wait for long duration (49 days), to speed up
# the simulation time, we disable leader to avoid the need to
# to simulate all the message/events (e.g. MLE adv) while thread
# is operational.
self.simulator.go(ONE_DAY)
netinfo = leader.history_netinfo(1)
self.assertTrue(netinfo[0]['age'].startswith('1 day'))
self.simulator.go(ONE_DAY)
netinfo = leader.history_netinfo(1)
self.assertTrue(netinfo[0]['age'].startswith('2 days'))
self.simulator.go((MAX_AGE_IN_DAYS - 3) * ONE_DAY)
netinfo = leader.history_netinfo(1)
self.assertTrue(netinfo[0]['age'].startswith('{} days'.format(MAX_AGE_IN_DAYS - 1)))
self.simulator.go(ONE_DAY)
netinfo = leader.history_netinfo(1)
self.assertTrue(netinfo[0]['age'].startswith('more than {} days'.format(MAX_AGE_IN_DAYS)))
self.simulator.go(2 * ONE_DAY)
netinfo = leader.history_netinfo(1)
self.assertTrue(netinfo[0]['age'].startswith('more than {} days'.format(MAX_AGE_IN_DAYS)))
# Start leader and child
leader.start()
self.simulator.go(SHORT_WAIT)
self.assertEqual(leader.get_state(), 'leader')
child.start()
self.simulator.go(SHORT_WAIT)
self.assertEqual(child.get_state(), 'child')
child_rloc16 = child.get_addr16()
leader_rloc16 = leader.get_addr16()
# Verify the `netinfo` history on child
netinfo = child.history_netinfo(2)
self.assertEqual(len(netinfo), 2)
self.assertEqual(netinfo[0]['role'], 'child')
self.assertEqual(netinfo[0]['mode'], 'n')
self.assertEqual(int(netinfo[0]['rloc16'], 16), child_rloc16)
self.assertEqual(netinfo[0]['partition-id'], leader.get_partition_id())
self.assertEqual(netinfo[1]['role'], 'detached')
# Change the child mode and verify that `netinfo` history
# records this change.
child.set_mode('rn')
self.simulator.go(SHORT_WAIT)
netinfo = child.history_netinfo(1)
self.assertEqual(len(netinfo), 1)
self.assertEqual(netinfo[0]['mode'], 'rn')
# Ping from leader to child and check the RX and TX history
# on child and leader.
child_mleid = child.get_mleid()
leader_mleid = leader.get_mleid()
ping_sizes = [10, 100, 1000]
num_msgs = len(ping_sizes)
for size in ping_sizes:
leader.ping(child_mleid, size=size)
leader_tx = leader.history_tx(num_msgs)
leader_rx = leader.history_rx(num_msgs)
child_tx = child.history_tx(num_msgs)
child_rx = child.history_rx(num_msgs)
for index in range(num_msgs):
self.assertEqual(leader_tx[index]['type'], 'ICMP6(EchoReqst)')
self.assertEqual(leader_tx[index]['sec'], 'yes')
self.assertEqual(leader_tx[index]['prio'], 'norm')
self.assertEqual(leader_tx[index]['tx-success'], 'yes')
self.assertEqual(leader_tx[index]['radio'], '15.4')
self.assertEqual(int(leader_tx[index]['to'], 16), child_rloc16)
self.assertEqual(leader_tx[index]['src'][1:-3], leader_mleid)
self.assertEqual(leader_tx[index]['dst'][1:-3], child_mleid)
self.assertEqual(child_rx[index]['type'], 'ICMP6(EchoReqst)')
self.assertEqual(child_rx[index]['sec'], 'yes')
self.assertEqual(child_rx[index]['prio'], 'norm')
self.assertEqual(child_rx[index]['radio'], '15.4')
self.assertEqual(int(child_rx[index]['from'], 16), leader_rloc16)
self.assertEqual(child_rx[index]['src'][1:-3], leader_mleid)
self.assertEqual(child_rx[index]['dst'][1:-3], child_mleid)
self.assertEqual(leader_rx[index]['type'], 'ICMP6(EchoReply)')
self.assertEqual(child_tx[index]['type'], 'ICMP6(EchoReply)')
self.assertEqual(leader_tx[index]['len'], child_rx[index]['len'])
self.assertEqual(leader_rx[index]['len'], child_tx[index]['len'])
if __name__ == '__main__':
# FIXME: We skip the test under distcheck build (the simulation
# under this build for some reason cannot seem to handle longer
# wait times - days up to 50 days in this test). We return error
# code 77 which indicates that this test case was skipped (in
# automake).
if os.getenv('DISTCHECK_BUILD') == '1':
sys.exit(77)
unittest.main()