Merge branch 'feature/monitor_filter_output' into 'master'

idf_monitor: add support for filtering options

See merge request idf/esp-idf!2486

components/esptool_py/Makefile.projbuild

@@ -85,7 +85,9 @@ endif
 simple_monitor: $(call prereq_if_explicit,%flash)
 	$(MONITOR_PYTHON) -m serial.tools.miniterm --rts 0 --dtr 0 --raw $(ESPPORT) $(MONITORBAUD)
 
-MONITOR_OPTS := --baud $(MONITORBAUD) --port $(ESPPORT) --toolchain-prefix $(CONFIG_TOOLPREFIX) --make "$(MAKE)"
+PRINT_FILTER ?=
+
+MONITOR_OPTS := --baud $(MONITORBAUD) --port $(ESPPORT) --toolchain-prefix $(CONFIG_TOOLPREFIX) --make "$(MAKE)" --print_filter "$(PRINT_FILTER)"
 
 monitor: $(call prereq_if_explicit,%flash)
 	$(summary) MONITOR

docs/en/get-started/idf-monitor.rst

@@ -105,6 +105,90 @@ Sometimes you may want to stop new output printed to screen, to see the log befo
 toggle the display (discard all serial data when the display is off) so that you can stop to see the log, and revert
 again quickly without quitting the monitor.
 
+Filtering the Output
+====================
+
+The IDF monitor can be invoked as ``make monitor PRINT_FILTER=""`` with
+specifying a custom ``PRINT_FILTER`` option for filtering outputs. The default
+value is an empty string which means that everything will be printed.
+Restrictions on what to print can be specified as a series of
+``<tag>:<log_level>`` items where ``<tag>`` is the tag string and
+``<log_level>`` is a character from set ``{N, E, W, I, D, V, *}`` referring to
+a level for :doc:`logging <../../api-reference/system/log>`. For example,
+``PRINT_FILTER="tag1:W"`` will match and print (only) the outputs written with
+``ESP_LOGW("tag1", ...)`` or at lower verbosity level, i.e. ``ESP_LOGE("tag1",
+...)``. Not specifying a
+``<log_level>`` or using ``*`` defaults to Verbose level.
+
+.. note::
+   The primary logging is set up at compilation time through the
+   :doc:`logging library<../../api-reference/system/log>`.
+   Output filtering by the IDF monitor is only a secondary solution because
+   one cannot filter something which has been disabled at compilation time.
+   The advantage of the secondary filtering is that one can use various
+   filtering options without recompiling the application.
+
+A restriction applies to tags when one wants to use them together with output
+filtering: they cannot contain spaces, asterisks ``*`` and semicolons ``:``.
+
+If the last line of the output is written without an end of line then the
+output filtering might get confused, i.e. the monitor starts to print the line and only
+later finds out that the line should have not been written. This is a known
+issue and can be avoided by always adding an end of line after printing
+something (especially when no output follows immediately afterwards).
+
+Examples Of Filtering Rules:
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+- Asterisk can be used to match any tags. However, specifying
+  ``PRINT_FILTER="*:I tag1:E"`` will print for ``tag1`` only errors because
+  the rule for ``tag1`` has a precedence over the rule for ``*``.
+- The default (empty) rule is equivalent to ``*:V`` because matching every tag
+  at level Verbose or lower means matching everything.
+- Rule ``"tag1:W tag1:E"`` is equivalent to ``"tag1:E"`` because any
+  consequent occurrence of the same tag name overwrites the previous one.
+- Rule ``"tag1:I tag2:W"`` will print only ``tag1`` at verbosity level Info or
+  lower and ``tag2`` at verbosity level Warning or lower.
+- Rule ``"tag1:I tag2:W tag3:N"`` is essentially equivalent to the previous
+  one because ``tag3:N`` specifies that ``tag3`` should not be printed.
+- ``tag3:N`` in rule ``"tag1:I tag2:W tag3:N *:V"`` is more meaningful because
+  in this context the result will be that ``tag3`` will not be printed,
+  ``tag1`` and ``tag2`` will be at the specified (or lower) verbosity level
+  and everything else will be printed by default.
+- ``"*:N"`` will suppress all outputs even prints made by something else than
+  the logging functions, e.g. ``printf``. For printing those outputs one need
+  to use ``*:E`` or higher verbosity level.
+- Rules ``"tag1:V"``, ``"tag1:v"``, ``"tag1:"``, ``"tag1:*"`` and ``"tag1"``
+  are all equivalent ones.
+
+A More Complex Filtering Example
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+The following log snippet was acquired using ``make monitor``::
+
+    load:0x40078000,len:13564
+    entry 0x40078d4c
+    E (31) esp_image: image at 0x30000 has invalid magic byte
+    W (31) esp_image: image at 0x30000 has invalid SPI mode 255
+    E (39) boot: Factory app partition is not bootable
+    I (568) cpu_start: Pro cpu up.
+    I (569) heap_init: Initializing. RAM available for dynamic allocation:
+    I (603) cpu_start: Pro cpu start user code
+    D (309) light_driver: [light_init, 74]:status: 1, mode: 2
+    D (318) vfs: esp_vfs_register_fd_range is successful for range <54; 64) and VFS ID 1
+    I (328) wifi: wifi driver task: 3ffdbf84, prio:23, stack:4096, core=0
+
+The captured output for ``make monitor PRINT_FILTER="wifi esp_image:E light_driver:I"`` is the following::
+
+    E (31) esp_image: image at 0x30000 has invalid magic byte
+    I (328) wifi: wifi driver task: 3ffdbf84, prio:23, stack:4096, core=0
+
+``make monitor PRINT_FILTER="light_driver:D esp_image:N boot:N cpu_start:N vfs:N wifi:N *:V"`` gives the following output::
+
+    load:0x40078000,len:13564
+    entry 0x40078d4c
+    I (569) heap_init: Initializing. RAM available for dynamic allocation:
+    D (309) light_driver: [light_init, 74]:status: 1, mode: 2
 
 Simple Monitor
 ==============

tools/idf_monitor.py

@@ -59,7 +59,7 @@ CTRL_Y = '\x19'
 CTRL_P = '\x10'
 CTRL_RBRACKET = '\x1d'  # Ctrl+]
 
-# ANSI terminal codes
+# ANSI terminal codes (if changed, regular expressions in LineMatcher need to be udpated)
 ANSI_RED = '\033[1;31m'
 ANSI_YELLOW = '\033[0;33m'
 ANSI_NORMAL = '\033[0m'
@@ -74,17 +74,20 @@ def yellow_print(message):
 def red_print(message):
     color_print(message, ANSI_RED)
 
-__version__ = "1.0"
+__version__ = "1.1"
 
 # Tags for tuples in queues
 TAG_KEY = 0
 TAG_SERIAL = 1
+TAG_SERIAL_FLUSH = 2
 
 # regex matches an potential PC value (0x4xxxxxxx)
 MATCH_PCADDR = re.compile(r'0x4[0-9a-f]{7}', re.IGNORECASE)
 
 DEFAULT_TOOLCHAIN_PREFIX = "xtensa-esp32-elf-"
 
+DEFAULT_PRINT_FILTER = ""
+
 class StoppableThread(object):
     """
     Provide a Thread-like class which can be 'cancelled' via a subclass-provided
@@ -165,7 +168,7 @@ class ConsoleReader(StoppableThread):
             # this is the way cancel() is implemented in pyserial 3.3 or newer,
             # older pyserial (3.1+) has cancellation implemented via 'select',
             # which does not work when console sends an escape sequence response
-            # 
+            #
             # even older pyserial (<3.1) does not have this method
             #
             # on Windows there is a different (also hacky) fix, applied above.
@@ -210,6 +213,57 @@ class SerialReader(StoppableThread):
             except:
                 pass
 
+class LineMatcher:
+    """
+    Assembles a dictionary of filtering rules based on the --print_filter
+    argument of idf_monitor. Then later it is used to match lines and
+    determine whether they should be shown on screen or not.
+    """
+    LEVEL_N = 0
+    LEVEL_E = 1
+    LEVEL_W = 2
+    LEVEL_I = 3
+    LEVEL_D = 4
+    LEVEL_V = 5
+
+    level = {'N': LEVEL_N, 'E': LEVEL_E, 'W': LEVEL_W, 'I': LEVEL_I, 'D': LEVEL_D,
+            'V': LEVEL_V, '*': LEVEL_V, '': LEVEL_V}
+
+    def __init__(self, print_filter):
+        self._dict = dict()
+        self._re = re.compile(r'^(?:\033\[[01];?[0-9]+m?)?([EWIDV]) \([0-9]+\) ([^:]+): ')
+        items = print_filter.split()
+        if len(items) == 0:
+            self._dict["*"] = self.LEVEL_V # default is to print everything
+        for f in items:
+            s = f.split(r':')
+            if len(s) == 1:
+                # specifying no warning level defaults to verbose level
+                lev = self.LEVEL_V
+            elif len(s) == 2:
+                if len(s[0]) == 0:
+                    raise ValueError('No tag specified in filter ' + f)
+                try:
+                    lev = self.level[s[1].upper()]
+                except KeyError:
+                    raise ValueError('Unknown warning level in filter ' + f)
+            else:
+                raise ValueError('Missing ":" in filter ' + f)
+            self._dict[s[0]] = lev
+    def match(self, line):
+        try:
+            m = self._re.search(line)
+            if m:
+                lev = self.level[m.group(1)]
+                if m.group(2) in self._dict:
+                    return self._dict[m.group(2)] >= lev
+                return self._dict.get("*", self.LEVEL_N) >= lev
+        except (KeyError, IndexError):
+            # Regular line written with something else than ESP_LOG*
+            # or an empty line.
+            pass
+        # We need something more than "*.N" for printing.
+        return self._dict.get("*", self.LEVEL_N) > self.LEVEL_N
 
 class Monitor(object):
     """
@@ -220,7 +274,7 @@ class Monitor(object):
 
     Main difference is that all event processing happens in the main thread, not the worker threads.
     """
-    def __init__(self, serial_instance, elf_file, make="make", toolchain_prefix=DEFAULT_TOOLCHAIN_PREFIX, eol="CRLF"):
+    def __init__(self, serial_instance, elf_file, print_filter, make="make", toolchain_prefix=DEFAULT_TOOLCHAIN_PREFIX, eol="CRLF"):
         super(Monitor, self).__init__()
         self.event_queue = queue.Queue()
         self.console = miniterm.Console()
@@ -236,9 +290,9 @@ class Monitor(object):
                 if c == unichr(0x7f):
                     c = unichr(8)    # map the BS key (which yields DEL) to backspace
                 return c
-            
-            self.console.getkey = types.MethodType(getkey_patched, self.console) 
-        
+
+            self.console.getkey = types.MethodType(getkey_patched, self.console)
+
         self.serial = serial_instance
         self.console_reader = ConsoleReader(self.console, self.event_queue)
         self.serial_reader = SerialReader(self.serial, self.event_queue)
@@ -256,10 +310,17 @@ class Monitor(object):
 
         # internal state
         self._pressed_menu_key = False
-        self._read_line = b""
+        self._last_line_part = b""
         self._gdb_buffer = b""
+        self._pc_address_buffer = b""
+        self._line_matcher = LineMatcher(print_filter)
+        self._invoke_processing_last_line_timer = None
+        self._force_line_print = False
         self._output_enabled = True
 
+    def invoke_processing_last_line(self):
+        self.event_queue.put((TAG_SERIAL_FLUSH, b''), False)
+
     def main_loop(self):
         self.console_reader.start()
         self.serial_reader.start()
@@ -270,12 +331,26 @@ class Monitor(object):
                     self.handle_key(data)
                 elif event_tag == TAG_SERIAL:
                     self.handle_serial_input(data)
+                    if self._invoke_processing_last_line_timer is not None:
+                        self._invoke_processing_last_line_timer.cancel()
+                    self._invoke_processing_last_line_timer = threading.Timer(1, self.invoke_processing_last_line)
+                    self._invoke_processing_last_line_timer.start()
+                    # If no futher data is received in the next short period
+                    # of time then the _invoke_processing_last_line_timer
+                    # generates an event which will result in the finishing of
+                    # the last line. This is fix for handling lines sent
+                    # without EOL.
+                elif event_tag == TAG_SERIAL_FLUSH:
+                    self.handle_serial_input(data, finalize_line=True)
                 else:
                     raise RuntimeError("Bad event data %r" % ((event_tag,data),))
         finally:
             try:
                 self.console_reader.stop()
                 self.serial_reader.stop()
+                # Cancelling _invoke_processing_last_line_timer is not
+                # important here because receiving empty data doesn't matter.
+                self._invoke_processing_last_line_timer = None
             except:
                 pass
             sys.stderr.write(ANSI_NORMAL + "\n")
@@ -298,20 +373,49 @@ class Monitor(object):
             except UnicodeEncodeError:
                 pass # this can happen if a non-ascii character was passed, ignoring
 
-    def handle_serial_input(self, data):
-        # this may need to be made more efficient, as it pushes out a byte
-        # at a time to the console
-        for b in data:
-            if self._output_enabled:
-                self.console.write_bytes(b)
-            if b == b'\n': # end of line
-                self.handle_serial_input_line(self._read_line.strip())
-                self._read_line = b""
-            else:
-                self._read_line += b
-            self.check_gdbstub_trigger(b)
-
-    def handle_serial_input_line(self, line):
+    def handle_serial_input(self, data, finalize_line=False):
+        sp = data.split(b'\n')
+        if self._last_line_part != b"":
+            # add unprocessed part from previous "data" to the first line
+            sp[0] = self._last_line_part + sp[0]
+            self._last_line_part = b""
+        if sp[-1] != b"":
+            # last part is not a full line
+            self._last_line_part = sp.pop()
+        for line in sp:
+            if line != b"":
+                if self._output_enabled and (self._force_line_print or self._line_matcher.match(line)):
+                    self.console.write_bytes(line + b'\n')
+                    self.handle_possible_pc_address_in_line(line)
+                self.check_gdbstub_trigger(line)
+                self._force_line_print = False
+        # Now we have the last part (incomplete line) in _last_line_part. By
+        # default we don't touch it and just wait for the arrival of the rest
+        # of the line. But after some time when we didn't received it we need
+        # to make a decision.
+        if finalize_line and self._last_line_part != b"":
+            if self._line_matcher.match(self._last_line_part):
+                self._force_line_print = True;
+                if self._output_enabled:
+                    self.console.write_bytes(self._last_line_part)
+                    self.handle_possible_pc_address_in_line(self._last_line_part)
+                self.check_gdbstub_trigger(self._last_line_part)
+                # It is possible that the incomplete line cuts in half the PC
+                # address. A small buffer is kept and will be used the next time
+                # handle_possible_pc_address_in_line is invoked to avoid this problem.
+                # MATCH_PCADDR matches 10 character long addresses. Therefore, we
+                # keep the last 9 characters.
+                self._pc_address_buffer = self._last_line_part[-9:]
+                # GDB sequence can be cut in half also. GDB sequence is 7
+                # characters long, therefore, we save the last 6 characters.
+                self._gdb_buffer = self._last_line_part[-6:]
+                self._last_line_part = b""
+        # else: keeping _last_line_part and it will be processed the next time
+        # handle_serial_input is invoked
+
+    def handle_possible_pc_address_in_line(self, line):
+        line = self._pc_address_buffer + line
+        self._pc_address_buffer = b""
         for m in re.finditer(MATCH_PCADDR, line):
             self.lookup_pc_address(m.group())
 
@@ -424,9 +528,10 @@ class Monitor(object):
         if not "?? ??:0" in translation:
             yellow_print(translation)
 
-    def check_gdbstub_trigger(self, c):
-        self._gdb_buffer = self._gdb_buffer[-6:] + c  # keep the last 7 characters seen
-        m = re.match(b"\\$(T..)#(..)", self._gdb_buffer) # look for a gdb "reason" for a break
+    def check_gdbstub_trigger(self, line):
+        line = self._gdb_buffer + line
+        self._gdb_buffer = b""
+        m = re.search(b"\\$(T..)#(..)", line) # look for a gdb "reason" for a break
         if m is not None:
             try:
                 chsum = sum(ord(p) for p in m.group(1)) & 0xFF
@@ -507,6 +612,11 @@ def main():
         'elf_file', help='ELF file of application',
         type=argparse.FileType('rb'))
 
+    parser.add_argument(
+        '--print_filter',
+        help="Filtering string",
+        default=DEFAULT_PRINT_FILTER)
+
     args = parser.parse_args()
 
     if args.port.startswith("/dev/tty."):
@@ -532,7 +642,7 @@ def main():
     except KeyError:
         pass  # not running a make jobserver
 
-    monitor = Monitor(serial_instance, args.elf_file.name, args.make, args.toolchain_prefix, args.eol)
+    monitor = Monitor(serial_instance, args.elf_file.name, args.print_filter, args.make, args.toolchain_prefix, args.eol)
 
     yellow_print('--- idf_monitor on {p.name} {p.baudrate} ---'.format(
         p=serial_instance))
@@ -541,6 +651,8 @@ def main():
         key_description(monitor.menu_key),
         key_description(monitor.menu_key),
         key_description(CTRL_H)))
+    if args.print_filter != DEFAULT_PRINT_FILTER:
+        yellow_print('--- Print filter: {} ---'.format(args.print_filter))
 
     monitor.main_loop()