From 277b89c946e6fdc764ee48726fcd3df1c189eda9 Mon Sep 17 00:00:00 2001 From: Klement Sekera Date: Fri, 28 Oct 2016 13:20:27 +0200 Subject: add vpp debugging support to test framework improve test documentation Change-Id: Ia9678aa2532ecb4cb33736aedb4a31aa3f2a3f93 Signed-off-by: Klement Sekera --- test/log.py | 71 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 71 insertions(+) create mode 100644 test/log.py (limited to 'test/log.py') diff --git a/test/log.py b/test/log.py new file mode 100644 index 00000000..38610b7e --- /dev/null +++ b/test/log.py @@ -0,0 +1,71 @@ +#!/usr/bin/env python + +import sys +import os +import logging + +""" @var formatting delimiter consisting of '=' characters """ +double_line_delim = '=' * 70 +""" @var formatting delimiter consisting of '-' characters """ +single_line_delim = '-' * 70 + + +def colorize(msg, color): + return color + msg + COLOR_RESET + + +class ColorFormatter(logging.Formatter): + + def init(self, fmt=None, datefmt=None): + super(ColorFormatter, self).__init__(fmt, datefmt) + + def format(self, record): + message = super(ColorFormatter, self).format(record) + if hasattr(record, 'color'): + message = colorize(message, record.color) + return message + +handler = logging.StreamHandler(sys.stdout) +handler.setFormatter(ColorFormatter()) + +global_logger = logging.getLogger() +global_logger.addHandler(handler) +try: + verbose = int(os.getenv("V", 0)) +except: + verbose = 0 + +# 40 = ERROR, 30 = WARNING, 20 = INFO, 10 = DEBUG, 0 = NOTSET (all messages) +if verbose >= 2: + log_level = 10 +elif verbose == 1: + log_level = 20 +else: + log_level = 40 + +scapy_logger = logging.getLogger("scapy.runtime") +scapy_logger.setLevel(logging.ERROR) + + +def getLogger(name): + logger = logging.getLogger(name) + logger.setLevel(log_level) + return logger + +# Static variables to store color formatting strings. +# +# These variables (RED, GREEN, YELLOW and LPURPLE) are used to configure +# the color of the text to be printed in the terminal. Variable COLOR_RESET +# is used to revert the text color to the default one. +if hasattr(sys.stdout, 'isatty') and sys.stdout.isatty(): + RED = '\033[91m' + GREEN = '\033[92m' + YELLOW = '\033[93m' + LPURPLE = '\033[94m' + COLOR_RESET = '\033[0m' +else: + RED = '' + GREEN = '' + YELLOW = '' + LPURPLE = '' + COLOR_RESET = '' -- cgit 1.2.3-korg From e4504c6320790bba27fccf3746eb38f75f4d2e95 Mon Sep 17 00:00:00 2001 From: Klement Sekera Date: Thu, 8 Dec 2016 10:16:41 +0100 Subject: BFD: fix timing in the main loop Properly wakeup the main process loop only when necessary to avoid missed events. Improve BFD unit test reliability and speed. Add timestamps to logs and replace Queue with more efficient deque. Change-Id: I01255a02057d3146917b43b669ccdc74f31ef0c8 Signed-off-by: Klement Sekera --- test/bfd.py | 9 +++--- test/framework.py | 46 ++++++++++++++++++------------- test/log.py | 3 +- test/test_bfd.py | 69 +++++++++++++++++++++++----------------------- test/vpp_papi_provider.py | 28 +++++++++++-------- vnet/vnet/bfd/bfd_debug.h | 2 ++ vnet/vnet/bfd/bfd_main.c | 70 +++++++++++++++++++++++++++++------------------ vnet/vnet/bfd/bfd_udp.c | 15 +++++++++- 8 files changed, 145 insertions(+), 97 deletions(-) (limited to 'test/log.py') diff --git a/test/bfd.py b/test/bfd.py index beacd80f..fe63264e 100644 --- a/test/bfd.py +++ b/test/bfd.py @@ -161,7 +161,8 @@ class VppBFDUDPSession(VppObject): def detect_mult(self): return self._detect_mult - def __init__(self, test, interface, peer_addr, local_addr=None, af=AF_INET): + def __init__(self, test, interface, peer_addr, local_addr=None, af=AF_INET, + desired_min_tx=100000, required_min_rx=100000, detect_mult=3): self._test = test self._interface = interface self._af = af @@ -169,9 +170,9 @@ class VppBFDUDPSession(VppObject): self._peer_addr = peer_addr self._peer_addr_n = socket.inet_pton(af, peer_addr) self._bs_index = None - self._desired_min_tx = 200000 # 0.2s - self._required_min_rx = 200000 # 0.2s - self._detect_mult = 3 # 3 packets need to be missed + self._desired_min_tx = desired_min_tx + self._required_min_rx = required_min_rx + self._detect_mult = detect_mult def add_vpp_config(self): is_ipv6 = 1 if AF_INET6 == self.af else 0 diff --git a/test/framework.py b/test/framework.py index e1f3ba54..c91f34f9 100644 --- a/test/framework.py +++ b/test/framework.py @@ -6,7 +6,7 @@ import tempfile import time import resource from time import sleep -from Queue import Queue +from collections import deque from threading import Thread from inspect import getdoc from hook import StepHook, PollHook @@ -41,9 +41,9 @@ class _PacketInfo(object): data = None -def pump_output(out, queue): +def pump_output(out, deque): for line in iter(out.readline, b''): - queue.put(line) + deque.append(line) class VppTestCase(unittest.TestCase): @@ -185,13 +185,13 @@ class VppTestCase(unittest.TestCase): # doesn't get called and we might end with a zombie vpp try: cls.run_vpp() - cls.vpp_stdout_queue = Queue() + cls.vpp_stdout_deque = deque() cls.vpp_stdout_reader_thread = Thread(target=pump_output, args=( - cls.vpp.stdout, cls.vpp_stdout_queue)) + cls.vpp.stdout, cls.vpp_stdout_deque)) cls.vpp_stdout_reader_thread.start() - cls.vpp_stderr_queue = Queue() + cls.vpp_stderr_deque = deque() cls.vpp_stderr_reader_thread = Thread(target=pump_output, args=( - cls.vpp.stderr, cls.vpp_stderr_queue)) + cls.vpp.stderr, cls.vpp_stderr_deque)) cls.vpp_stderr_reader_thread.start() cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls) if cls.step: @@ -239,27 +239,26 @@ class VppTestCase(unittest.TestCase): cls.vpp.terminate() del cls.vpp - if hasattr(cls, 'vpp_stdout_queue'): + if hasattr(cls, 'vpp_stdout_deque'): cls.logger.info(single_line_delim) cls.logger.info('VPP output to stdout while running %s:', cls.__name__) cls.logger.info(single_line_delim) f = open(cls.tempdir + '/vpp_stdout.txt', 'w') - while not cls.vpp_stdout_queue.empty(): - line = cls.vpp_stdout_queue.get_nowait() - f.write(line) - cls.logger.info('VPP stdout: %s' % line.rstrip('\n')) + vpp_output = "".join(cls.vpp_stdout_deque) + f.write(vpp_output) + cls.logger.info('\n%s', vpp_output) + cls.logger.info(single_line_delim) - if hasattr(cls, 'vpp_stderr_queue'): + if hasattr(cls, 'vpp_stderr_deque'): cls.logger.info(single_line_delim) cls.logger.info('VPP output to stderr while running %s:', cls.__name__) cls.logger.info(single_line_delim) f = open(cls.tempdir + '/vpp_stderr.txt', 'w') - while not cls.vpp_stderr_queue.empty(): - line = cls.vpp_stderr_queue.get_nowait() - f.write(line) - cls.logger.info('VPP stderr: %s' % line.rstrip('\n')) + vpp_output = "".join(cls.vpp_stderr_deque) + f.write(vpp_output) + cls.logger.info('\n%s', vpp_output) cls.logger.info(single_line_delim) @classmethod @@ -280,6 +279,15 @@ class VppTestCase(unittest.TestCase): """ Clear trace before running each test""" if self.vpp_dead: raise Exception("VPP is dead when setting up the test") + time.sleep(.1) + self.vpp_stdout_deque.append( + "--- test setUp() for %s.%s(%s) starts here ---\n" % + (self.__class__.__name__, self._testMethodName, + self._testMethodDoc)) + self.vpp_stderr_deque.append( + "--- test setUp() for %s.%s(%s) starts here ---\n" % + (self.__class__.__name__, self._testMethodName, + self._testMethodDoc)) self.vapi.cli("clear trace") # store the test instance inside the test class - so that objects # holding the class can access instance methods (like assertEqual) @@ -297,14 +305,14 @@ class VppTestCase(unittest.TestCase): i.enable_capture() @classmethod - def pg_start(cls): + def pg_start(cls, sleep_time=1): """ Enable the packet-generator and send all prepared packet streams Remove the packet streams afterwards """ cls.vapi.cli("trace add pg-input 50") # 50 is maximum cls.vapi.cli('packet-generator enable') - sleep(1) # give VPP some time to process the packets + sleep(sleep_time) # give VPP some time to process the packets for stream in cls.pg_streams: cls.vapi.cli('packet-generator delete %s' % stream) cls.pg_streams = [] diff --git a/test/log.py b/test/log.py index 38610b7e..5a6219ce 100644 --- a/test/log.py +++ b/test/log.py @@ -26,7 +26,8 @@ class ColorFormatter(logging.Formatter): return message handler = logging.StreamHandler(sys.stdout) -handler.setFormatter(ColorFormatter()) +handler.setFormatter(ColorFormatter(fmt='%(asctime)s,%(msecs)03d %(message)s', + datefmt="%H:%M:%S")) global_logger = logging.getLogger() global_logger.addHandler(handler) diff --git a/test/test_bfd.py b/test/test_bfd.py index 58f12645..b48c3cc4 100644 --- a/test/test_bfd.py +++ b/test/test_bfd.py @@ -8,12 +8,12 @@ from framework import * from util import ppp -class BFDCLITestCase(VppTestCase): - """Bidirectional Forwarding Detection (BFD) - CLI""" +class BFDAPITestCase(VppTestCase): + """Bidirectional Forwarding Detection (BFD) - API""" @classmethod def setUpClass(cls): - super(BFDCLITestCase, cls).setUpClass() + super(BFDAPITestCase, cls).setUpClass() try: cls.create_pg_interfaces([0]) @@ -21,7 +21,7 @@ class BFDCLITestCase(VppTestCase): cls.pg0.resolve_arp() except Exception: - super(BFDCLITestCase, cls).tearDownClass() + super(BFDAPITestCase, cls).tearDownClass() raise def test_add_bfd(self): @@ -80,7 +80,7 @@ class BFDTestSession(object): self.interface = interface self.bfd_values = { 'my_discriminator': 0, - 'desired_min_tx_interval': 500000, + 'desired_min_tx_interval': 100000, 'detect_mult': detect_mult, 'diag': BFDDiagCode.no_diagnostic, } @@ -98,7 +98,7 @@ class BFDTestSession(object): p = self.create_packet() self.test.logger.debug(ppp("Sending packet:", p)) self.test.pg0.add_stream([p]) - self.test.pg_start() + self.test.pg_start(sleep_time=0) def verify_packet(self, packet): """ Verify correctness of BFD layer. """ @@ -116,7 +116,7 @@ class BFDTestCase(VppTestCase): def setUpClass(cls): super(BFDTestCase, cls).setUpClass() try: - cls.create_pg_interfaces([0, 1]) + cls.create_pg_interfaces([0]) cls.pg0.config_ip4() cls.pg0.generate_remote_hosts() cls.pg0.configure_ipv4_neighbors() @@ -137,6 +137,7 @@ class BFDTestCase(VppTestCase): def tearDown(self): self.vapi.want_bfd_events(enable_disable=0) + self.vapi.collect_events() # clear the event queue if not self.vpp_dead: self.vpp_session.remove_vpp_config() super(BFDTestCase, self).tearDown() @@ -144,7 +145,7 @@ class BFDTestCase(VppTestCase): def verify_event(self, event, expected_state): """ Verify correctness of event values. """ e = event - self.logger.debug("Event: %s" % repr(e)) + self.logger.debug("BFD: Event: %s" % repr(e)) self.assert_equal(e.bs_index, self.vpp_session.bs_index, "BFD session index") self.assert_equal(e.sw_if_index, self.vpp_session.interface.sw_if_index, @@ -166,6 +167,7 @@ class BFDTestCase(VppTestCase): self.assert_equal(e.state, expected_state, BFDState) def wait_for_bfd_packet(self, timeout=1): + self.logger.info("BFD: Waiting for BFD packet") p = self.pg0.wait_for_packet(timeout=timeout) bfd = p[BFD] if bfd is None: @@ -178,22 +180,23 @@ class BFDTestCase(VppTestCase): return p def test_slow_timer(self): - """ Slow timer """ - + """ verify slow periodic control frames while session down """ self.pg_enable_capture([self.pg0]) - expected_packets = 10 - self.logger.info("Waiting for %d BFD packets" % expected_packets) + expected_packets = 3 + self.logger.info("BFD: Waiting for %d BFD packets" % expected_packets) self.wait_for_bfd_packet() for i in range(expected_packets): before = time.time() self.wait_for_bfd_packet() after = time.time() + # spec says the range should be <0.75, 1>, allow extra 0.05 margin + # to work around timing issues self.assert_in_range( - after - before, 0.75, 1, "time between slow packets") + after - before, 0.70, 1.05, "time between slow packets") before = after def test_zero_remote_min_rx(self): - """ Zero RemoteMinRxInterval """ + """ no packets when zero BFD RemoteMinRxInterval """ self.pg_enable_capture([self.pg0]) p = self.wait_for_bfd_packet() self.test_session.update(my_discriminator=randint(0, 40000000), @@ -210,50 +213,48 @@ class BFDTestCase(VppTestCase): return raise Exception(ppp("Received unexpected BFD packet:", p)) - def bfd_conn_up(self): + def bfd_session_up(self): self.pg_enable_capture([self.pg0]) - self.logger.info("Waiting for slow hello") + self.logger.info("BFD: Waiting for slow hello") p = self.wait_for_bfd_packet() - self.logger.info("Sending Init") + self.logger.info("BFD: Sending Init") self.test_session.update(my_discriminator=randint(0, 40000000), your_discriminator=p[BFD].my_discriminator, state=BFDState.init, - required_min_rx_interval=500000) + required_min_rx_interval=100000) self.test_session.send_packet() - self.logger.info("Waiting for event") + self.logger.info("BFD: Waiting for event") e = self.vapi.wait_for_event(1, "bfd_udp_session_details") self.verify_event(e, expected_state=BFDState.up) - self.logger.info("Session is Up") + self.logger.info("BFD: Session is Up") self.test_session.update(state=BFDState.up) - def test_conn_up(self): - """ Basic connection up """ - self.bfd_conn_up() + def test_session_up(self): + """ bring BFD session up """ + self.bfd_session_up() def test_hold_up(self): - """ Hold BFD up """ - self.bfd_conn_up() + """ hold BFD session up """ + self.bfd_session_up() for i in range(5): self.wait_for_bfd_packet() self.test_session.send_packet() def test_conn_down(self): - """ Session down after inactivity """ - self.bfd_conn_up() + """ verify session goes down after inactivity """ + self.bfd_session_up() self.wait_for_bfd_packet() - self.assert_equal( - 0, len(self.vapi.collect_events()), - "number of bfd events") + self.assert_equal(len(self.vapi.collect_events()), 0, + "number of bfd events") self.wait_for_bfd_packet() - self.assert_equal( - 0, len(self.vapi.collect_events()), - "number of bfd events") + self.assert_equal(len(self.vapi.collect_events()), 0, + "number of bfd events") e = self.vapi.wait_for_event(1, "bfd_udp_session_details") self.verify_event(e, expected_state=BFDState.down) @unittest.skip("this test is not working yet") def test_large_required_min_rx(self): - self.bfd_conn_up() + self.bfd_session_up() interval = 5000000 self.test_session.update(required_min_rx_interval=interval) self.test_session.send_packet() diff --git a/test/vpp_papi_provider.py b/test/vpp_papi_provider.py index 5e80a03e..c45518bd 100644 --- a/test/vpp_papi_provider.py +++ b/test/vpp_papi_provider.py @@ -2,6 +2,7 @@ import os import fnmatch import time from hook import Hook +from collections import deque # Sphinx creates auto-generated documentation by importing the python source # files and collecting the docstrings from them. The NO_VPP_PAPI flag allows the @@ -48,7 +49,7 @@ class VppPapiProvider(object): jsonfiles.append(os.path.join(root, filename)) self.papi = VPP(jsonfiles) - self._events = list() + self._events = deque() def register_hook(self, hook): """Replace hook registration with new hook @@ -59,19 +60,25 @@ class VppPapiProvider(object): self.hook = hook def collect_events(self): + """ Collect all events from the internal queue and clear the queue. """ e = self._events - self._events = list() + self._events = deque() return e def wait_for_event(self, timeout, name=None): + """ Wait for and return next event. """ + if self._events: + self.test_class.logger.debug("Not waiting, event already queued") limit = time.time() + timeout while time.time() < limit: if self._events: - e = self._events.pop(0) + e = self._events.popleft() if name and type(e).__name__ != name: raise Exception( "Unexpected event received: %s, expected: %s" % (type(e).__name__, name)) + self.test_class.logger.debug("Returning event %s:%s" % + (name, e)) return e time.sleep(0) # yield if name is not None: @@ -79,8 +86,10 @@ class VppPapiProvider(object): raise Exception("Event did not occur within timeout") def __call__(self, name, event): + """ Enqueue event in the internal event queue. """ # FIXME use the name instead of relying on type(e).__name__ ? # FIXME #2 if this throws, it is eaten silently, Ole? + self.test_class.logger.debug("New event: %s: %s" % (name, event)) self._events.append(event) def connect(self): @@ -93,7 +102,7 @@ class VppPapiProvider(object): self.papi.disconnect() def api(self, api_fn, api_args, expected_retval=0): - """Call API function and check it's return value + """ Call API function and check it's return value. Call the appropriate hooks before and after the API call :param api_fn: API function to call @@ -107,14 +116,13 @@ class VppPapiProvider(object): if hasattr(reply, 'retval') and reply.retval != expected_retval: msg = "API call failed, expected retval == %d, got %s" % ( expected_retval, repr(reply)) - self.test_class.logger.error(msg) + self.test_class.logger.info(msg) raise Exception(msg) self.hook.after_api(api_fn.__name__, api_args) return reply def cli(self, cli): - """ - Execute a CLI, calling the before/after hooks appropriately. + """ Execute a CLI, calling the before/after hooks appropriately. :param cli: CLI to execute :returns: CLI output @@ -128,8 +136,7 @@ class VppPapiProvider(object): return r.reply.decode().rstrip('\x00') def ppcli(self, cli): - """ - Helping method to print CLI command in case of info logging level. + """ Helper method to print CLI command in case of info logging level. :param cli: CLI to execute :returns: CLI output @@ -165,8 +172,7 @@ class VppPapiProvider(object): return self.api(self.papi.sw_interface_dump, args) def sw_interface_set_table(self, sw_if_index, is_ipv6, table_id): - """ - Set the IPvX Table-id for the Interface + """ Set the IPvX Table-id for the Interface :param sw_if_index: :param is_ipv6: diff --git a/vnet/vnet/bfd/bfd_debug.h b/vnet/vnet/bfd/bfd_debug.h index c11e6d9f..0072ff8f 100644 --- a/vnet/vnet/bfd/bfd_debug.h +++ b/vnet/vnet/bfd/bfd_debug.h @@ -47,6 +47,7 @@ _s = format (_s, "%6.02f:DBG:%s:%d:%s():" fmt, vlib_time_now (vm), \ __file, __LINE__, __func__, ##__VA_ARGS__); \ printf ("%s\n", _s); \ + fflush (stdout); \ vec_free (_s); \ } \ while (0); @@ -60,6 +61,7 @@ _s = format (_s, "%6.02f:ERR:%s:%d:%s():" fmt, vlib_time_now (vm), \ __file, __LINE__, __func__, ##__VA_ARGS__); \ printf ("%s\n", _s); \ + fflush (stdout); \ vec_free (_s); \ } \ while (0); diff --git a/vnet/vnet/bfd/bfd_main.c b/vnet/vnet/bfd/bfd_main.c index 26b9fe31..ffc04ee4 100644 --- a/vnet/vnet/bfd/bfd_main.c +++ b/vnet/vnet/bfd/bfd_main.c @@ -59,8 +59,8 @@ typedef enum BFD_INPUT_N_NEXT, } bfd_input_next_t; -static void bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, - u64 now); +static void bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now, + int handling_wakeup); static void bfd_set_defaults (bfd_main_t * bm, bfd_session_t * bs) @@ -88,7 +88,8 @@ bfd_set_diag (bfd_session_t * bs, bfd_diag_code_e code) } static void -bfd_set_state (bfd_main_t * bm, bfd_session_t * bs, bfd_state_e new_state) +bfd_set_state (bfd_main_t * bm, bfd_session_t * bs, + bfd_state_e new_state, int handling_wakeup) { if (bs->local_state != new_state) { @@ -96,7 +97,7 @@ bfd_set_state (bfd_main_t * bm, bfd_session_t * bs, bfd_state_e new_state) bfd_state_string (bs->local_state), bfd_state_string (new_state)); bs->local_state = new_state; - bfd_on_state_change (bm, bs, clib_cpu_time_now ()); + bfd_on_state_change (bm, bs, clib_cpu_time_now (), handling_wakeup); } } @@ -175,7 +176,8 @@ bfd_recalc_detection_time (bfd_main_t * bm, bfd_session_t * bs) } static void -bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now) +bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now, + int handling_wakeup) { u64 next = 0; u64 rx_timeout = 0; @@ -212,12 +214,18 @@ bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now) (i64) (bs->wheel_time_clocks - clib_cpu_time_now ()) / bm->cpu_cps, bs->bs_idx); timing_wheel_insert (&bm->wheel, bs->wheel_time_clocks, bs->bs_idx); + if (!handling_wakeup) + { + vlib_process_signal_event (bm->vlib_main, + bm->bfd_process_node_index, + BFD_EVENT_RESCHEDULE, bs->bs_idx); + } } } static void bfd_set_desired_min_tx (bfd_main_t * bm, bfd_session_t * bs, u64 now, - u32 desired_min_tx_us) + u32 desired_min_tx_us, int handling_wakeup) { bs->desired_min_tx_us = desired_min_tx_us; bs->desired_min_tx_clocks = bfd_us_to_clocks (bm, bs->desired_min_tx_us); @@ -227,7 +235,7 @@ bfd_set_desired_min_tx (bfd_main_t * bm, bfd_session_t * bs, u64 now, bfd_recalc_detection_time (bm, bs); bfd_recalc_tx_interval (bm, bs); bfd_calc_next_tx (bm, bs, now); - bfd_set_timer (bm, bs, now); + bfd_set_timer (bm, bs, now, handling_wakeup); } void @@ -295,12 +303,12 @@ bfd_session_set_flags (u32 bs_idx, u8 admin_up_down) bfd_session_t *bs = pool_elt_at_index (bm->sessions, bs_idx); if (admin_up_down) { - bfd_set_state (bm, bs, BFD_STATE_down); + bfd_set_state (bm, bs, BFD_STATE_down, 0); } else { bfd_set_diag (bs, BFD_DIAG_CODE_neighbor_sig_down); - bfd_set_state (bm, bs, BFD_STATE_admin_down); + bfd_set_state (bm, bs, BFD_STATE_admin_down, 0); } return 0; } @@ -344,7 +352,8 @@ bfd_input_format_trace (u8 * s, va_list * args) } static void -bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now) +bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now, + int handling_wakeup) { BFD_DBG ("State changed: %U", format_bfd_session, bs); bfd_event (bm, bs); @@ -353,20 +362,24 @@ bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now) case BFD_STATE_admin_down: bfd_set_desired_min_tx (bm, bs, now, clib_max (bs->config_desired_min_tx_us, - BFD_DEFAULT_DESIRED_MIN_TX_US)); + BFD_DEFAULT_DESIRED_MIN_TX_US), + handling_wakeup); break; case BFD_STATE_down: bfd_set_desired_min_tx (bm, bs, now, clib_max (bs->config_desired_min_tx_us, - BFD_DEFAULT_DESIRED_MIN_TX_US)); + BFD_DEFAULT_DESIRED_MIN_TX_US), + handling_wakeup); break; case BFD_STATE_init: bfd_set_desired_min_tx (bm, bs, now, clib_max (bs->config_desired_min_tx_us, - BFD_DEFAULT_DESIRED_MIN_TX_US)); + BFD_DEFAULT_DESIRED_MIN_TX_US), + handling_wakeup); break; case BFD_STATE_up: - bfd_set_desired_min_tx (bm, bs, now, bs->config_desired_min_tx_us); + bfd_set_desired_min_tx (bm, bs, now, bs->config_desired_min_tx_us, + handling_wakeup); break; } } @@ -441,7 +454,8 @@ bfd_init_control_frame (vlib_buffer_t * b, bfd_session_t * bs) static void bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt, - bfd_main_t * bm, bfd_session_t * bs, u64 now) + bfd_main_t * bm, bfd_session_t * bs, u64 now, + int handling_wakeup) { if (!bs->remote_min_rx_us) { @@ -472,7 +486,7 @@ bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt, { BFD_DBG ("No need to send control frame now"); } - bfd_set_timer (bm, bs, now); + bfd_set_timer (bm, bs, now, handling_wakeup); } void @@ -485,13 +499,14 @@ bfd_send_final (vlib_main_t * vm, vlib_buffer_t * b, bfd_session_t * bs) } static void -bfd_check_rx_timeout (bfd_main_t * bm, bfd_session_t * bs, u64 now) +bfd_check_rx_timeout (bfd_main_t * bm, bfd_session_t * bs, u64 now, + int handling_wakeup) { if (bs->last_rx_clocks + bs->detection_time_clocks < now) { BFD_DBG ("Rx timeout, session goes down"); bfd_set_diag (bs, BFD_DIAG_CODE_det_time_exp); - bfd_set_state (bm, bs, BFD_STATE_down); + bfd_set_state (bm, bs, BFD_STATE_down, handling_wakeup); } } @@ -508,7 +523,7 @@ bfd_on_timeout (vlib_main_t * vm, vlib_node_runtime_t * rt, bfd_main_t * bm, abort (); break; case BFD_STATE_down: - bfd_send_periodic (vm, rt, bm, bs, now); + bfd_send_periodic (vm, rt, bm, bs, now, 1); break; case BFD_STATE_init: BFD_ERR ("Unexpected timeout when in %s state", @@ -516,8 +531,8 @@ bfd_on_timeout (vlib_main_t * vm, vlib_node_runtime_t * rt, bfd_main_t * bm, abort (); break; case BFD_STATE_up: - bfd_check_rx_timeout (bm, bs, now); - bfd_send_periodic (vm, rt, bm, bs, now); + bfd_check_rx_timeout (bm, bs, now, 1); + bfd_send_periodic (vm, rt, bm, bs, now, 1); break; } } @@ -602,7 +617,7 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f) { bfd_session_t *bs = pool_elt_at_index (bm->sessions, *event_data); - bfd_send_periodic (vm, rt, bm, bs, now); + bfd_send_periodic (vm, rt, bm, bs, now, 1); } while (0); break; @@ -710,6 +725,7 @@ bfd_get_session (bfd_main_t * bm, bfd_transport_t t) { bfd_session_t *result; pool_get (bm->sessions, result); + memset (result, 0, sizeof (*result)); result->bs_idx = result - bm->sessions; result->transport = t; result->local_discr = random_u32 (&bm->random_seed); @@ -871,17 +887,17 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx) if (BFD_STATE_admin_down == bs->remote_state) { bfd_set_diag (bs, BFD_DIAG_CODE_neighbor_sig_down); - bfd_set_state (bm, bs, BFD_STATE_down); + bfd_set_state (bm, bs, BFD_STATE_down, 0); } else if (BFD_STATE_down == bs->local_state) { if (BFD_STATE_down == bs->remote_state) { - bfd_set_state (bm, bs, BFD_STATE_init); + bfd_set_state (bm, bs, BFD_STATE_init, 0); } else if (BFD_STATE_init == bs->remote_state) { - bfd_set_state (bm, bs, BFD_STATE_up); + bfd_set_state (bm, bs, BFD_STATE_up, 0); } } else if (BFD_STATE_init == bs->local_state) @@ -889,7 +905,7 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx) if (BFD_STATE_up == bs->remote_state || BFD_STATE_init == bs->remote_state) { - bfd_set_state (bm, bs, BFD_STATE_up); + bfd_set_state (bm, bs, BFD_STATE_up, 0); } } else /* BFD_STATE_up == bs->local_state */ @@ -897,7 +913,7 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx) if (BFD_STATE_down == bs->remote_state) { bfd_set_diag (bs, BFD_DIAG_CODE_neighbor_sig_down); - bfd_set_state (bm, bs, BFD_STATE_down); + bfd_set_state (bm, bs, BFD_STATE_down, 0); } } } diff --git a/vnet/vnet/bfd/bfd_udp.c b/vnet/vnet/bfd/bfd_udp.c index 44a4a18d..9d75e3ad 100644 --- a/vnet/vnet/bfd/bfd_udp.c +++ b/vnet/vnet/bfd/bfd_udp.c @@ -26,6 +26,9 @@ typedef struct mhash_t bfd_session_idx_by_bfd_key; } bfd_udp_main_t; +static vlib_node_registration_t bfd_udp4_input_node; +static vlib_node_registration_t bfd_udp6_input_node; + bfd_udp_main_t bfd_udp_main; void bfd_udp_transport_to_buffer (vlib_main_t *vm, vlib_buffer_t *b, @@ -510,12 +513,22 @@ static uword bfd_udp_input (vlib_main_t *vm, vlib_node_runtime_t *rt, if (BFD_UDP_ERROR_NONE == error0) { /* if everything went fine, check for poll bit, if present, re-use - the buffer and based on (now update) session parameters, send the + the buffer and based on (now updated) session parameters, send the final packet back */ const bfd_pkt_t *pkt = vlib_buffer_get_current (b0); if (bfd_pkt_get_poll (pkt)) { bfd_send_final (vm, b0, bs); + if (is_ipv6) + { + vlib_node_increment_counter (vm, bfd_udp6_input_node.index, + b0->error, 1); + } + else + { + vlib_node_increment_counter (vm, bfd_udp4_input_node.index, + b0->error, 1); + } next0 = BFD_UDP_INPUT_NEXT_REPLY; } } -- cgit 1.2.3-korg From 6c7440ca95fe3508c083ac4d2ecf7eca459b7f8e Mon Sep 17 00:00:00 2001 From: Klement Sekera Date: Fri, 23 Dec 2016 09:16:39 +0100 Subject: make test: add log.txt Always create a log.txt under test's temporary directory containing V=2 output for debugging purposes. Change-Id: If149c8126f42f80724ee17b63c411ddec6645f85 Signed-off-by: Klement Sekera --- test/framework.py | 4 ++++ test/log.py | 17 +++++++++-------- 2 files changed, 13 insertions(+), 8 deletions(-) (limited to 'test/log.py') diff --git a/test/framework.py b/test/framework.py index 1c3e56cc..1b745ff3 100644 --- a/test/framework.py +++ b/test/framework.py @@ -13,6 +13,7 @@ from vpp_pg_interface import VppPGInterface from vpp_lo_interface import VppLoInterface from vpp_papi_provider import VppPapiProvider from scapy.packet import Raw +from logging import FileHandler, DEBUG from log import * """ @@ -175,6 +176,9 @@ class VppTestCase(unittest.TestCase): cls.logger = getLogger(cls.__name__) cls.tempdir = tempfile.mkdtemp( prefix='vpp-unittest-' + cls.__name__ + '-') + file_handler = FileHandler("%s/log.txt" % cls.tempdir) + file_handler.setLevel(DEBUG) + cls.logger.addHandler(file_handler) cls.shm_prefix = cls.tempdir.split("/")[-1] os.chdir(cls.tempdir) cls.logger.info("Temporary dir is %s, shm prefix is %s", diff --git a/test/log.py b/test/log.py index 5a6219ce..cca542b4 100644 --- a/test/log.py +++ b/test/log.py @@ -24,13 +24,6 @@ class ColorFormatter(logging.Formatter): if hasattr(record, 'color'): message = colorize(message, record.color) return message - -handler = logging.StreamHandler(sys.stdout) -handler.setFormatter(ColorFormatter(fmt='%(asctime)s,%(msecs)03d %(message)s', - datefmt="%H:%M:%S")) - -global_logger = logging.getLogger() -global_logger.addHandler(handler) try: verbose = int(os.getenv("V", 0)) except: @@ -44,13 +37,21 @@ elif verbose == 1: else: log_level = 40 +handler = logging.StreamHandler(sys.stdout) +handler.setFormatter(ColorFormatter(fmt='%(asctime)s,%(msecs)03d %(message)s', + datefmt="%H:%M:%S")) +handler.setLevel(log_level) + +global_logger = logging.getLogger() +global_logger.addHandler(handler) + scapy_logger = logging.getLogger("scapy.runtime") scapy_logger.setLevel(logging.ERROR) def getLogger(name): logger = logging.getLogger(name) - logger.setLevel(log_level) + logger.setLevel(logging.DEBUG) return logger # Static variables to store color formatting strings. -- cgit 1.2.3-korg From 52e84f3cad6078e89031dafd789a8df57c1d7e1f Mon Sep 17 00:00:00 2001 From: Klement Sekera Date: Fri, 13 Jan 2017 07:25:25 +0100 Subject: make test: improve test results printing Accomodate longer test descriptions by increasing the headings size. Change-Id: I51c90b8d91feaa83b78972d0802d3054f8510f36 Signed-off-by: Klement Sekera --- test/framework.py | 4 ++-- test/log.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) (limited to 'test/log.py') diff --git a/test/framework.py b/test/framework.py index b2c6b9e4..a6b07f14 100644 --- a/test/framework.py +++ b/test/framework.py @@ -665,11 +665,11 @@ class VppTestResult(unittest.TestResult): unittest.TestResult.stopTest(self, test) if self.verbosity > 0: self.stream.writeln(single_line_delim) - self.stream.writeln("%-60s%s" % (self.getDescription(test), + self.stream.writeln("%-73s%s" % (self.getDescription(test), self.result_string)) self.stream.writeln(single_line_delim) else: - self.stream.writeln("%-60s%s" % (self.getDescription(test), + self.stream.writeln("%-73s%s" % (self.getDescription(test), self.result_string)) def printErrors(self): diff --git a/test/log.py b/test/log.py index cca542b4..1e541d38 100644 --- a/test/log.py +++ b/test/log.py @@ -5,9 +5,9 @@ import os import logging """ @var formatting delimiter consisting of '=' characters """ -double_line_delim = '=' * 70 +double_line_delim = '=' * 78 """ @var formatting delimiter consisting of '-' characters """ -single_line_delim = '-' * 70 +single_line_delim = '-' * 78 def colorize(msg, color): -- cgit 1.2.3-korg