fw: fix error logging

- Keep track of logged exceptions inside log_error itself.
- signal: log the exception, if there is one  in the finally clause of
  the  signal wrapper; this will ensure that the error will be logged
  closer to the command that originated.
- entrypoint: use log.log_error for top-level error logging, rather than
  the  entrypoint logger directly; this will ensure that errors are not
  repeated unnecessarily.
- Log CTRL-C message at zeroth indent level to make it easier to see in
  the  non-verbose output where it occurred.

4 files changed, 24 insertions, 15 deletions

diff --git a/wa/framework/entrypoint.py b/wa/framework/entrypoint.py
index ed95462c..e7123085 100644
--- a/wa/framework/entrypoint.py
+++ b/wa/framework/entrypoint.py
@@ -107,10 +107,9 @@ def main():
         command = commands[args.command]
         sys.exit(command.execute(config, args))
 
-    except KeyboardInterrupt:
-        logging.info('Got CTRL-C. Aborting.')
+    except KeyboardInterrupt as e:
+        log.log_error(e, logger)
         sys.exit(3)
     except Exception as e:  # pylint: disable=broad-except
-        if not getattr(e, 'logged', None):
-            log.log_error(e, logger)
+        log.log_error(e, logger)
         sys.exit(2)
diff --git a/wa/framework/execution.py b/wa/framework/execution.py
index 82b18065..fc94f240 100644
--- a/wa/framework/execution.py
+++ b/wa/framework/execution.py
@@ -233,9 +233,7 @@ class ExecutionContext(object):
             except WorkloadError as e:
                 job.set_status(Status.FAILED)
                 self.add_event(e.message)
-                if not getattr(e, 'logged', None):
-                    log.log_error(e, self.logger)
-                    e.logged = True
+                log.log_error(e, self.logger)
                 failed_ids.append(job.id)
 
                 if self.cm.run_config.bail_on_init_failure:
@@ -428,9 +426,7 @@ class Runner(object):
         except Exception as e: # pylint: disable=broad-except
             job.set_status(Status.FAILED)
             context.add_event(e.message)
-            if not getattr(e, 'logged', None):
-                log.log_error(e, self.logger)
-                e.logged = True
+            log.log_error(e, self.logger)
             if isinstance(e, ExecutionError):
                 raise e
             elif isinstance(e, TargetError):
@@ -470,9 +466,7 @@ class Runner(object):
                     job.run(context)
             except Exception as e:
                 job.set_status(Status.FAILED)
-                if not getattr(e, 'logged', None):
-                    log.log_error(e, self.logger)
-                    e.logged = True
+                log.log_error(e, self.logger)
                 if isinstance(e, TargetError) or isinstance(e, TimeoutError):
                     context.tm.verify_target_responsive()
                 raise e
diff --git a/wa/framework/signal.py b/wa/framework/signal.py
index 27842846..c35e496b 100644
--- a/wa/framework/signal.py
+++ b/wa/framework/signal.py
@@ -19,6 +19,7 @@ This module wraps louie signalling mechanism. It relies on modified version of l
 that has prioritization added to handler invocation.
 
 """
+import sys
 import logging
 from contextlib import contextmanager
 
@@ -298,7 +299,7 @@ def send(signal, sender=dispatcher.Anonymous, *args, **kwargs):
     return dispatcher.send(signal, sender, *args, **kwargs)
 
 
-# This will normally be set to log_error() by init_logging(); see wa.framework/log.py.
+# This will normally be set to log_error() by init_logging(); see wa.utils.log
 # Done this way to prevent a circular import dependency.
 log_error_func = logger.error
 
@@ -337,6 +338,9 @@ def wrap(signal_name, sender=dispatcher.Anonymous,*args, **kwargs):
         yield
         send_func(success_signal, sender, *args, **kwargs)
     finally:
+        exc_type, exc, tb = sys.exc_info()
+        if exc:
+            log_error_func(exc)
         send_func(after_signal, sender, *args, **kwargs)
 
 
diff --git a/wa/utils/log.py b/wa/utils/log.py
index 61ebac46..f3a3018f 100644
--- a/wa/utils/log.py
+++ b/wa/utils/log.py
@@ -152,6 +152,13 @@ def dedent():
     _indent_level -= 1
 
 
+def set_indent_level(level):
+    global _indent_level
+    old_level = _indent_level
+    _indent_level = level
+    return old_level
+
+
 def log_error(e, logger, critical=False):
     """
     Log the specified Exception as an error. The Error message will be formatted
@@ -163,13 +170,18 @@ def log_error(e, logger, critical=False):
                level, otherwise it will be logged as ``logging.ERROR``.
 
     """
+    if getattr(e, 'logged', None):
+        return
+
     if critical:
         log_func = logger.critical
     else:
         log_func = logger.error
 
     if isinstance(e, KeyboardInterrupt):
-        log_func('Got CTRL-C. Aborting.')
+        old_level = set_indent_level(0)
+        logger.info('Got CTRL-C. Aborting.')
+        set_indent_level(old_level)
     elif isinstance(e, WAError) or isinstance(e, DevlibError):
         log_func(str(e))
     elif isinstance(e, subprocess.CalledProcessError):