Logging adjustments

Add function for setting the stderr log level and adjust some log
statements.

Bug: 41

Change-Id: I3cb44d78c5316949da331ca91fca25592f3f5907

pw_cli/py/pw_cli/__main__.py

diff --git a/pw_cli/py/pw_cli/__main__.py b/pw_cli/py/pw_cli/__main__.py
index db99075..ffa5cfd 100644
--- a/pw_cli/py/pw_cli/__main__.py
+++ b/pw_cli/py/pw_cli/__main__.py
@@ -102,8 +102,8 @@
 
     # Set root log level; but then remove the arg to avoid breaking the command.
     if 'loglevel' in args_as_dict:
-        logging.getLogger().setLevel(
-            getattr(logging, args_as_dict['loglevel'].upper()))
+        pw_cli.log.set_level(getattr(logging,
+                                     args_as_dict['loglevel'].upper()))
         del args_as_dict['loglevel']
 
     # Run the command and exit with the appropriate status.

pw_cli/py/pw_cli/log.py

diff --git a/pw_cli/py/pw_cli/log.py b/pw_cli/py/pw_cli/log.py
index 7fc1c55..f573028 100644
--- a/pw_cli/py/pw_cli/log.py
+++ b/pw_cli/py/pw_cli/log.py
@@ -25,6 +25,7 @@
 LOGLEVEL_STDOUT = 21
 
 _LOG = logging.getLogger(__name__)
+_STDERR_HANDLER = logging.StreamHandler()
 
 
 def main():
@@ -40,7 +41,8 @@
     _LOG.debug('Adding 1 to i')
 
 
-def install(use_color: Optional[bool] = None) -> None:
+def install(level: int = logging.INFO,
+            use_color: Optional[bool] = None) -> None:
     """Configure the system logger for the default pw command log format."""
 
     colors = pw_cli.color.colors(
@@ -65,13 +67,11 @@
     root = logging.getLogger()
     root.setLevel(logging.DEBUG)
 
-    # Skip debug-level statements when printing to the terminal.
-    stderr_handler = logging.StreamHandler()
-    stderr_handler.setLevel(logging.INFO)
-    stderr_handler.setFormatter(
+    _STDERR_HANDLER.setLevel(level)
+    _STDERR_HANDLER.setFormatter(
         logging.Formatter(timestamp_fmt + '%(levelname)s %(message)s',
                           '%Y%m%d %H:%M:%S'))
-    root.addHandler(stderr_handler)
+    root.addHandler(_STDERR_HANDLER)
 
     # Shorten all the log levels to 3 characters for column-aligned logs.
     # Color the logs using ANSI codes.
@@ -87,6 +87,11 @@
     # pylint: enable=bad-whitespace
 
 
+def set_level(log_level: int):
+    """Sets the log level for logs to stderr."""
+    _STDERR_HANDLER.setLevel(log_level)
+
+
 # Note: normally this shouldn't be done at the top level without a try/catch
 # around the pw_cli.plugins registry import, since pw_cli might not be
 # installed.

pw_presubmit/py/pw_presubmit/pigweed_presubmit.py

diff --git a/pw_presubmit/py/pw_presubmit/pigweed_presubmit.py b/pw_presubmit/py/pw_presubmit/pigweed_presubmit.py
index 48aaacc..46d3a95 100755
--- a/pw_presubmit/py/pw_presubmit/pigweed_presubmit.py
+++ b/pw_presubmit/py/pw_presubmit/pigweed_presubmit.py
@@ -323,11 +323,10 @@
     files = set()
 
     for line in process.stdout.splitlines():
-        _LOG.debug('processing line %r', line)
         path = line.strip().lstrip(b'/').replace(b':', b'/').decode()
         path = ctx.repository_root.joinpath(path)
         if path.is_file():
-            _LOG.debug('  file %s', path)
+            _LOG.debug('Found file %s', path)
             files.add(path)
 
     return files

pw_presubmit/py/pw_presubmit/tools.py

diff --git a/pw_presubmit/py/pw_presubmit/tools.py b/pw_presubmit/py/pw_presubmit/tools.py
index b589b38..5fa3a4b 100644
--- a/pw_presubmit/py/pw_presubmit/tools.py
+++ b/pw_presubmit/py/pw_presubmit/tools.py
@@ -59,7 +59,6 @@
 from inspect import signature
 
 _LOG: logging.Logger = logging.getLogger(__name__)
-_LOG.setLevel(logging.DEBUG)
 
 PathOrStr = Union[Path, str]
 
@@ -610,17 +609,17 @@
 
 def call(*args, **kwargs) -> None:
     """Optional subprocess wrapper that causes a PresubmitFailure on errors."""
-    _LOG.debug('call: %s %s', args, kwargs)
+    attributes = ', '.join(f'{k}={v}' for k, v in sorted(kwargs.items()))
+    command = ' '.join(shlex.quote(str(arg)) for arg in args)
+    _LOG.debug('[RUN] %s\n%s', attributes, command)
+
     process = subprocess.run(args,
                              stdout=subprocess.PIPE,
                              stderr=subprocess.STDOUT,
                              **kwargs)
     logfunc = _LOG.warning if process.returncode else _LOG.debug
 
-    logfunc('[COMMAND] %s\n%s',
-            ', '.join(f'{k}={v}' for k, v in sorted(kwargs.items())),
-            ' '.join(shlex.quote(str(arg)) for arg in args))
-
+    logfunc('[FINISHED] %s\n%s', attributes, command)
     logfunc('[RESULT] %s with return code %d',
             'Failed' if process.returncode else 'Passed', process.returncode)