tools: Some additions to IDF Monitor's timestamps

Additions to https://github.com/espressif/esp-idf/pull/7021

docs/en/api-guides/tools/idf-monitor.rst

@@ -52,6 +52,9 @@ For easy interaction with IDF Monitor, use the keyboard shortcuts given in the t
    * - * Ctrl+L
      - Stop/resume log output saved to file
      - Creates a file in the project directory and the output is written to that file until this is disabled with the same keyboard shortcut (or IDF Monitor exits).                
+   * - * Ctrl+I (or I)
+     - Stop/resume printing timestamps
+     - IDF Monitor can print a timestamp in the beginning of each line. The timestamp format can be changed by the --timestamp-format command line argument.
    * - * Ctrl+H (or H)
      - Display all keyboard shortcuts
      -                
@@ -268,7 +271,6 @@ Known Issues with IDF Monitor
 Issues Observed on Windows
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 
-- If in the Windows environment you receive the error "winpty: command not found", fix it by running ``pacman -S winpty``.
 - Arrow keys, as well as some other keys, do not work in GDB due to Windows Console limitations.
 - Occasionally, when "idf.py" or "make" exits, it might stall for up to 30 seconds before IDF Monitor resumes.
 - When "gdb" is run, it might stall for a short time before it begins communicating with the GDBStub.

tools/idf_monitor.py

@@ -41,7 +41,7 @@ import subprocess
 import threading
 import time
 from builtins import bytes, object
-from typing import BinaryIO, Callable, List, Optional, Union
+from typing import AnyStr, BinaryIO, Callable, List, Optional, Union
 
 import serial.tools.miniterm as miniterm
 from idf_monitor_base import (COREDUMP_DECODE_DISABLE, COREDUMP_DECODE_INFO, COREDUMP_DONE, COREDUMP_IDLE,
@@ -53,8 +53,8 @@ from idf_monitor_base.chip_specific_config import get_chip_config
 from idf_monitor_base.console_parser import ConsoleParser
 from idf_monitor_base.console_reader import ConsoleReader
 from idf_monitor_base.constants import (CMD_APP_FLASH, CMD_ENTER_BOOT, CMD_MAKE, CMD_OUTPUT_TOGGLE, CMD_RESET,
-                                        CMD_STOP, CMD_TOGGLE_LOGGING, CTRL_H, CTRL_T, TAG_CMD, TAG_KEY, TAG_SERIAL,
+                                        CMD_STOP, CMD_TOGGLE_LOGGING, CMD_TOGGLE_TIMESTAMPS, CTRL_H, CTRL_T, TAG_CMD,
-                                        TAG_SERIAL_FLUSH)
+                                        TAG_KEY, TAG_SERIAL, TAG_SERIAL_FLUSH)
 from idf_monitor_base.exceptions import SerialStopException
 from idf_monitor_base.line_matcher import LineMatcher
 from idf_monitor_base.output_helpers import normal_print, red_print, yellow_print
@@ -88,14 +88,23 @@ 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, print_filter, make='make', encrypted=False,
+    def __init__(
-                 toolchain_prefix=DEFAULT_TOOLCHAIN_PREFIX, eol='CRLF',
+            self,
-                 decode_coredumps=COREDUMP_DECODE_INFO,
+            serial_instance,                               # type: serial.Serial
-                 decode_panic=PANIC_DECODE_DISABLE,
+            elf_file,                                      # type: str
-                 target='esp32',
+            print_filter,                                  # type: str
-                 websocket_client=None, enable_address_decoding=True,
+            make='make',                                   # type: str
-                 timestamps=False):
+            encrypted=False,                               # type: bool
-        # type: (serial.Serial, str, str, str, bool, str, str, str, str, str, WebSocketClient, bool) -> None
+            toolchain_prefix=DEFAULT_TOOLCHAIN_PREFIX,     # type: str
+            eol='CRLF',                                    # type: str
+            decode_coredumps=COREDUMP_DECODE_INFO,         # type: str
+            decode_panic=PANIC_DECODE_DISABLE,             # type: str
+            target='esp32',                                # type: str
+            websocket_client=None,                         # type: WebSocketClient
+            enable_address_decoding=True,                  # type: bool
+            timestamps=False,                              # type: bool
+            timestamp_format=''                            # type: str
+    ):
         super(Monitor, self).__init__()
         self.event_queue = queue.Queue()  # type: queue.Queue
         self.cmd_queue = queue.Queue()  # type: queue.Queue
@@ -144,6 +153,7 @@ class Monitor(object):
         self.gdb_exit = False
         self.start_cmd_sent = False
         self._timestamps = timestamps
+        self._timestamp_format = timestamp_format
 
     def invoke_processing_last_line(self):
         # type: () -> None
@@ -568,6 +578,9 @@ class Monitor(object):
         else:
             self.start_logging()
 
+    def toggle_timestamps(self):  # type: () -> None
+        self._timestamps = not self._timestamps
+
     def start_logging(self):  # type: () -> None
         if not self._log_file:
             name = 'log.{}.{}.txt'.format(os.path.splitext(os.path.basename(self.elf_file))[0],
@@ -589,22 +602,25 @@ class Monitor(object):
             finally:
                 self._log_file = None
 
-    def _print(self, string, console_printer=None):  # type: (Union[str, bytes], Optional[Callable]) -> None
+    def _print(self, string, console_printer=None):  # type: (AnyStr, Optional[Callable]) -> None
         if console_printer is None:
             console_printer = self.console.write_bytes
-        if self._output_enabled:
+        if self._timestamps and (self._output_enabled or self._log_file):
-            if self._timestamps:
+            t = datetime.datetime.now().strftime(self._timestamp_format)
-                t = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S ")
+            # "string" is not guaranteed to be a full line. Timestamps should be only at the beginning of lines.
             if isinstance(string, type(u'')):
-                    console_printer(t + string)
+                search_patt = '\n'
-                else:
+                replacement = '\n' + t + ' '
-                    console_printer(t.encode('ascii') + string)
             else:
+                search_patt = b'\n'                             # type: ignore
+                replacement = b'\n' + t.encode('ascii') + b' '  # type: ignore
+            string = string.replace(search_patt, replacement)
+        if self._output_enabled:
             console_printer(string)
         if self._log_file:
             try:
                 if isinstance(string, type(u'')):
-                    string = string.encode()
+                    string = string.encode()  # type: ignore
                 self._log_file.write(string)  # type: ignore
             except Exception as e:
                 red_print('\nCannot write to file: {}'.format(e))
@@ -638,6 +654,8 @@ class Monitor(object):
             self.output_toggle()
         elif cmd == CMD_TOGGLE_LOGGING:
             self.toggle_logging()
+        elif cmd == CMD_TOGGLE_TIMESTAMPS:
+            self.toggle_timestamps()
         elif cmd == CMD_ENTER_BOOT:
             self.serial.setDTR(high)  # IO0=HIGH
             self.serial.setRTS(low)  # EN=LOW, chip in reset
@@ -744,6 +762,12 @@ def main():  # type: () -> None
         default=False,
         action='store_true')
 
+    parser.add_argument(
+        '--timestamp-format',
+        default=os.environ.get('ESP_IDF_MONITOR_TIMESTAMP_FORMAT', '%Y-%m-%d %H:%M:%S'),
+        help='Set a strftime()-compatible timestamp format'
+    )
+
     args = parser.parse_args()
 
     # GDB uses CreateFile to open COM port, which requires the COM name to be r'\\.\COMx' if the COM
@@ -787,7 +811,7 @@ def main():  # type: () -> None
                           args.toolchain_prefix, args.eol,
                           args.decode_coredumps, args.decode_panic, args.target,
                           ws, enable_address_decoding=not args.disable_address_decoding,
-                          timestamps=args.timestamps)
+                          timestamps=args.timestamps, timestamp_format=args.timestamp_format)
 
         yellow_print('--- idf_monitor on {p.name} {p.baudrate} ---'.format(p=serial_instance))
         yellow_print('--- Quit: {} | Menu: {} | Help: {} followed by {} ---'.format(

tools/idf_monitor_base/console_parser.py

@@ -22,8 +22,8 @@ except ImportError:
 import serial.tools.miniterm as miniterm
 
 from .constants import (CMD_APP_FLASH, CMD_ENTER_BOOT, CMD_MAKE, CMD_OUTPUT_TOGGLE, CMD_RESET, CMD_STOP,
-                        CMD_TOGGLE_LOGGING, CTRL_A, CTRL_F, CTRL_H, CTRL_L, CTRL_P, CTRL_R, CTRL_RBRACKET, CTRL_T,
+                        CMD_TOGGLE_LOGGING, CMD_TOGGLE_TIMESTAMPS, CTRL_A, CTRL_F, CTRL_H, CTRL_I, CTRL_L, CTRL_P,
-                        CTRL_X, CTRL_Y, TAG_CMD, TAG_KEY, __version__)
+                        CTRL_R, CTRL_RBRACKET, CTRL_T, CTRL_X, CTRL_Y, TAG_CMD, TAG_KEY, __version__)
 from .output_helpers import red_print, yellow_print
 
 key_description = miniterm.key_description
@@ -72,6 +72,8 @@ class ConsoleParser(object):
             ret = (TAG_CMD, CMD_OUTPUT_TOGGLE)
         elif c == CTRL_L:  # Toggle saving output into file
             ret = (TAG_CMD, CMD_TOGGLE_LOGGING)
+        elif c in [CTRL_I, 'i', 'I']:  # Toggle printing timestamps
+            ret = (TAG_CMD, CMD_TOGGLE_TIMESTAMPS)
         elif c == CTRL_P:
             yellow_print('Pause app (enter bootloader mode), press Ctrl-T Ctrl-R to restart')
             # to fast trigger pause without press menu key
@@ -99,6 +101,7 @@ class ConsoleParser(object):
             ---    {appmake:14} Build & flash app only
             ---    {output:14} Toggle output display
             ---    {log:14} Toggle saving output into file
+            ---    {timestamps:14} Toggle printing timestamps
             ---    {pause:14} Reset target into bootloader to pause app via RTS line
             ---    {menuexit:14} Exit program
         """.format(version=__version__,
@@ -109,6 +112,7 @@ class ConsoleParser(object):
                    appmake=key_description(CTRL_A) + ' (or A)',
                    output=key_description(CTRL_Y),
                    log=key_description(CTRL_L),
+                   timestamps=key_description(CTRL_I) + ' (or I)',
                    pause=key_description(CTRL_P),
                    menuexit=key_description(CTRL_X) + ' (or X)')
         return textwrap.dedent(text)

tools/idf_monitor_base/constants.py

@@ -17,6 +17,7 @@ CTRL_A = '\x01'
 CTRL_B = '\x02'
 CTRL_F = '\x06'
 CTRL_H = '\x08'
+CTRL_I = '\x09'
 CTRL_R = '\x12'
 CTRL_T = '\x14'
 CTRL_Y = '\x19'
@@ -33,6 +34,7 @@ CMD_APP_FLASH = 4
 CMD_OUTPUT_TOGGLE = 5
 CMD_TOGGLE_LOGGING = 6
 CMD_ENTER_BOOT = 7
+CMD_TOGGLE_TIMESTAMPS = 8
 
 # Tags for tuples in queues
 TAG_KEY = 0

tools/idf_py_actions/serial_ext.py

@@ -71,7 +71,7 @@ def action_extensions(base_actions, project_path):
 
         return result
 
-    def monitor(action, ctx, args, print_filter, monitor_baud, encrypted):
+    def monitor(action, ctx, args, print_filter, monitor_baud, encrypted, timestamps, timestamp_format):
         """
         Run idf_monitor.py to watch build output
         """
@@ -118,6 +118,12 @@ def action_extensions(base_actions, project_path):
         if encrypted:
             monitor_args += ['--encrypted']
 
+        if timestamps:
+            monitor_args += ['--timestamps']
+
+        if timestamp_format:
+            monitor_args += ['--timestamp-format', timestamp_format]
+
         idf_py = [PYTHON] + _get_commandline_options(ctx)  # commands to re-run idf.py
         monitor_args += ['-m', ' '.join("'%s'" % a for a in idf_py)]
 
@@ -214,7 +220,17 @@ def action_extensions(base_actions, project_path):
                                  'IDF Monitor will invoke encrypted-flash and encrypted-app-flash targets '
                                  'if this option is set. This option is set by default if IDF Monitor was invoked '
                                  'together with encrypted-flash or encrypted-app-flash target.'),
+                    }, {
+                        'names': ['--timestamps'],
+                        'is_flag': True,
+                        'help': 'Print a time stamp in the beginning of each line.',
+                    }, {
+                        'names': ['--timestamp-format'],
+                        'help': ('Set the formatting of timestamps compatible with strftime(). '
+                                 'For example, "%Y-%m-%d %H:%M:%S".'),
+                        'default': None
                     }
+
                 ],
                 'order_dependencies': [
                     'flash',