ec3po: make debug logs more user-friendly to read

This change does two things:
(1) it adds by default that both directions i.e. user to EC and EC to
user get logged to debug at full lines (or line limit)
(2) it hides the per interrupt print statements behind a command:
raw-debug

This is to allow servod logs to easily contain the MCU logs for all
connected devices: servo(s), Cr50, EC, and more.

BUG=chromium:932820
TEST=manual testing

sudo servod -s 19 -d | grep LogConsole
// observe console output (with logger overhead as prefix)

with crrev.com/c/1688610:

dut-control ec_uart_raw_debug:on
// observe in the logs how messages like below return
[...] - |DBG|-i->'an 0'

Change-Id: I864ac3411a002385505a192db3f300eb7bd71b47
Signed-off-by: Ruben Rodriguez Buchillon <coconutruben@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/1688363
Reviewed-by: Aseda Aboagye <aaboagye@chromium.org>
Reviewed-by: Mary Ruthven <mruthven@chromium.org>

1 files changed, 38 insertions, 7 deletions

diff --git a/util/ec3po/console.py b/util/ec3po/console.py
index 913aee4498..a730d3d8ec 100755
--- a/util/ec3po/console.py
+++ b/util/ec3po/console.py
@@ -133,6 +133,9 @@ class Console(object):
     pending_oobm_cmd: A string containing the pending OOBM command.
     interrogation_mode: A string containing the current mode of whether
       interrogations are performed with the EC or not and how often.
+    raw_debug: Flag to indicate whether per interrupt data should be logged to
+      debug
+    output_line_log_buffer: buffer for lines coming from the EC to log to debug
   """
 
   def __init__(self, master_pty, user_pty, interface_pty, cmd_pipe, dbg_pipe,
@@ -179,6 +182,8 @@ class Console(object):
     self.interrogation_mode = 'auto'
     self.timestamp_enabled = True
     self.look_buffer = ''
+    self.raw_debug = False
+    self.output_line_log_buffer = ''
 
   def __str__(self):
     """Show internal state of Console object as a string."""
@@ -201,6 +206,23 @@ class Console(object):
     string.append('look_buffer: \'%s\'' % self.look_buffer)
     return '\n'.join(string)
 
+  def LogConsoleOutput(self, data):
+    """Log to debug user MCU output to master_pty when line is filled.
+
+    Args:
+      data: string received from MCU
+    """
+    output_data = '%s%s' % (self.output_line_log_buffer, data)
+    ends_in_nl = output_data[-1] == '\n'
+    data_lines = output_data.splitlines()
+    for line in data_lines[:-1]:
+      self.logger.debug(line)
+    if ends_in_nl:
+      self.logger.debug(data_lines[-1])
+      self.output_line_log_buffer = ''
+    else:
+      self.output_line_log_buffer = data_lines[-1]
+
   def PrintHistory(self):
     """Print the history of entered commands."""
     fd = self.master_pty
@@ -763,6 +785,12 @@ class Console(object):
       self.logger.info('%sabling uart timestamps.',
                        'En' if self.timestamp_enabled else 'Dis')
 
+    elif cmd[0] == 'rawdebug':
+      mode = cmd[1].lower()
+      self.raw_debug = mode == 'on'
+      self.logger.info('%sabling per interrupt debug logs.',
+                       'En' if self.raw_debug else 'Dis')
+
     elif cmd[0] == 'interrogate' and len(cmd) >= 2:
       enhanced = False
       mode = cmd[1]
@@ -939,9 +967,11 @@ def StartLoop(console, command_active, shutdown_pipe=None):
             continue_looping = False
           else:
             # Write it to the user console.
-            console.logger.debug('|CMD|-%s->\'%s\'',
-                ('u' if master_connected else '') +
-                ('i' if command_active.value else ''), data.strip())
+            if console.raw_debug:
+              console.logger.debug('|CMD|-%s->\'%s\'',
+                                   ('u' if master_connected else '') +
+                                   ('i' if command_active.value else ''),
+                                   data.strip())
             if master_connected:
               os.write(console.master_pty, data)
             if command_active.value:
@@ -958,10 +988,12 @@ def StartLoop(console, command_active, shutdown_pipe=None):
               # Search look buffer for enhanced EC image string.
               console.CheckBufferForEnhancedImage(data)
             # Write it to the user console.
-            if len(data) > 1:
+            if len(data) > 1 and console.raw_debug:
               console.logger.debug('|DBG|-%s->\'%s\'',
-                  ('u' if master_connected else '') +
-                  ('i' if command_active.value else ''), data.strip())
+                                   ('u' if master_connected else '') +
+                                   ('i' if command_active.value else ''),
+                                   data.strip())
+            console.LogConsoleOutput(data)
             if master_connected:
               end = len(data) - 1
               if console.timestamp_enabled:
@@ -984,7 +1016,6 @@ def StartLoop(console, command_active, shutdown_pipe=None):
               # timestamp required on next input
               if data[end] == '\n':
                 tm_req = True
-
               os.write(console.master_pty, data_tm)
             if command_active.value:
               os.write(console.interface_pty, data)