fw/execution: change how error events get added

Rather than relying on a custom Logger with a context to add events when
they are logged, have the runner register hooks for corresponding
signals that do that.

The issue with the previous approach is that the event ended up
being added too late -- after the current job was already cleared, so
all events were added at run level.

With the new approach, the event will be added when it is first logged,
while there is still a current job being set. There will be no
duplication for Exceptions being re-raised and handled at different
levels because log_error() will ensure that each Exception is logged
only once.

wa/framework/execution.py

@@ -232,7 +232,6 @@ class ExecutionContext(object):
                 job.initialize(self)
             except WorkloadError as e:
                 job.set_status(Status.FAILED)
-                self.add_event(e.message)
                 log.log_error(e, self.logger)
                 failed_ids.append(job.id)
 
@@ -342,11 +341,11 @@ class Executor(object):
             self.logger.warn('There were warnings during execution.')
             self.logger.warn('Please see {}'.format(output.logfile))
 
-    def _error_signalled_callback(self):
+    def _error_signalled_callback(self, record):
         self.error_logged = True
         signal.disconnect(self._error_signalled_callback, signal.ERROR_LOGGED)
 
-    def _warning_signalled_callback(self):
+    def _warning_signalled_callback(self, record):
         self.warning_logged = True
         signal.disconnect(self._warning_signalled_callback, signal.WARNING_LOGGED)
 
@@ -362,7 +361,6 @@ class Runner(object):
 
     def __init__(self, context, pm):
         self.logger = logging.getLogger('runner')
-        self.logger.context = context
         self.context = context
         self.pm = pm
         self.output = self.context.output
@@ -393,6 +391,8 @@ class Runner(object):
 
     def initialize_run(self):
         self.logger.info('Initializing run')
+        signal.connect(self._error_signalled_callback, signal.ERROR_LOGGED)
+        signal.connect(self._warning_signalled_callback, signal.WARNING_LOGGED)
         self.context.start_run()
         self.pm.initialize()
         log.indent()
@@ -411,6 +411,8 @@ class Runner(object):
         for job in self.context.completed_jobs:
             job.finalize(self.context)
         log.dedent()
+        signal.disconnect(self._error_signalled_callback, signal.ERROR_LOGGED)
+        signal.disconnect(self._warning_signalled_callback, signal.WARNING_LOGGED)
 
     def run_next_job(self, context):
         job = context.start_job()
@@ -427,7 +429,6 @@ class Runner(object):
                 raise e
             else:
                 job.set_status(Status.FAILED)
-                context.add_event(e.message)
             if isinstance(e, TargetNotRespondingError):
                 raise e
             elif isinstance(e, TargetError):
@@ -523,5 +524,11 @@ class Runner(object):
     def send(self, s):
         signal.send(s, self, self.context)
 
+    def _error_signalled_callback(self, record):
+        self.context.add_event(record.getMessage())
+
+    def _warning_signalled_callback(self, record):
+        self.context.add_event(record.getMessage())
+
     def __str__(self):
         return 'runner'

wa/utils/log.py

@@ -44,28 +44,6 @@ _indent_width = 4
 _console_handler = None
 
 
-class ContextLogger(logging.Logger):
-
-    def __init__(self, name, context=None):
-        super(ContextLogger, self).__init__(name)
-        self.context = context
-
-    def warning(self, message):
-        if self.context:
-            self.context.add_event(message)
-        super(ContextLogger, self).warning(message)
-
-    def warn(self, message):
-        if self.context:
-            self.context.add_event(message)
-        super(ContextLogger, self).warn(message)
-
-    def error(self, message):
-        if self.context:
-            self.context.add_event(message)
-        super(ContextLogger, self).error(message)
-
-
 def init(verbosity=logging.INFO, color=True, indent_with=4,
          regular_fmt='%(levelname)-8s %(message)s',
          verbose_fmt='%(asctime)s %(levelname)-8s %(name)10.10s: %(message)s',
@@ -73,7 +51,6 @@ def init(verbosity=logging.INFO, color=True, indent_with=4,
     global _indent_width, _console_handler
     _indent_width = indent_with
     signal.log_error_func = lambda m: log_error(m, signal.logger)
-    logging.setLoggerClass(ContextLogger)
 
     root_logger = logging.getLogger()
     root_logger.setLevel(logging.DEBUG)
@@ -214,9 +191,9 @@ class ErrorSignalHandler(logging.Handler):
 
     def emit(self, record):
         if record.levelno == logging.ERROR:
-            signal.send(signal.ERROR_LOGGED, self)
+            signal.send(signal.ERROR_LOGGED, self, record)
         elif record.levelno == logging.WARNING:
-            signal.send(signal.WARNING_LOGGED, self)
+            signal.send(signal.WARNING_LOGGED, self, record)
 
 
 class LineFormatter(logging.Formatter):