framework/log.py

   1 # coding=utf-8
   2 # Copyright (c) 2013-2016, 2019 Intel Corporation
   3 #
   4 # Permission is hereby granted, free of charge, to any person obtaining a
   5 # copy of this software and associated documentation files (the "Software"),
   6 # to deal in the Software without restriction, including without limitation
   7 # the rights to use, copy, modify, merge, publish, distribute, sublicense,
   8 # and/or sell copies of the Software, and to permit persons to whom the
   9 # Software is furnished to do so, subject to the following conditions:
  10 #
  11 # The above copyright notice and this permission notice (including the next
  12 # paragraph) shall be included in all copies or substantial portions of the
  13 # Software.
  14 #
  15 # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  16 # IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  17 # FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
  18 # THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  19 # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
  20 # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
  21 # IN THE SOFTWARE.
  22
  23 """ Module for terminal logging
  24
  25 This module provides a class LogManager, which acts as a state manager
  26 returning BaseLog derived instances to individual tests.
  27
  28 """
  29
  30 import sys
  31 import abc
  32 import itertools
  33 import threading
  34 import collections
  35 from http.server import HTTPServer, BaseHTTPRequestHandler
  36
  37 import json
  38
  39 from framework.core import PIGLIT_CONFIG
  40 from framework import grouptools
  41
  42 __all__ = ['LogManager']
  43
  44
  45 class BaseLog(metaclass=abc.ABCMeta):
  46     """ Abstract base class for Log objects
  47
  48     It provides a lock, which should be used to lock whenever the shared state is
  49     modified, or when printing to the screen (or both).
  50
  51     Arguments:
  52     state -- the state dict from LogManager
  53
  54     """
  55     SUMMARY_KEYS = set([
  56         'pass', 'fail', 'warn', 'crash', 'skip', 'dmesg-warn', 'dmesg-fail',
  57         'dry-run', 'timeout'])
  58     _LOCK = None
  59
  60     def __init__(self, state, state_lock):
  61         self._LOCK = state_lock
  62         self._state = state
  63         self._pad = len(str(state['total']))
  64
  65     @abc.abstractmethod
  66     def start(self, name):
  67         """ Called before test run starts
  68
  69         This method is used to print things before the test starts
  70
  71         """
  72
  73     @abc.abstractmethod
  74     def log(self, status):
  75         """ Print the result of the test
  76
  77         This method is run after the test completes, and is used to log the
  78         actual result of the test
  79
  80         """
  81
  82     @abc.abstractmethod
  83     def summary(self):
  84         """ Print a final summary
  85
  86         This method is run at the end of the test run, and is used to print a
  87         final summary of the run
  88
  89         """
  90
  91
  92 class QuietLog(BaseLog):
  93     """ A logger providing minimal status output
  94
  95     This logger provides only a ninja like [x/y] pass: z, fail: w ... output.
  96
  97     It uses \r to print over the same line when printing to a tty. If
  98     sys.stdout is not a tty then it prints \n at the end of the line instead
  99
 100     Arguments:
 101     status -- the status to print
 102
 103     """
 104     _test_counter = itertools.count()
 105
 106     def __init__(self, *args, **kwargs):
 107         super(QuietLog, self).__init__(*args, **kwargs)
 108
 109         # If the output is a tty we can use '\r' (return, no linebreak) to
 110         # print over the existing line, if stdout isn't a tty that will not
 111         # work (and can break systems like jenkins), so we print a \n instead
 112         if sys.stdout.isatty():
 113             self._endcode = '\r'
 114         else:
 115             self._endcode = '\n'
 116
 117         self.__counter = next(self._test_counter)
 118
 119     def start(self, name):
 120         # This cannot be done in the constructor, since the constructor gets
 121         # called for the final summary too.
 122         with self._LOCK:
 123             self._state['running'].append(self.__counter)
 124
 125     def _log(self, status):
 126         """ non-locked helper for logging
 127
 128         To allow for code sharing with a subclass using a non-recursive lock we
 129         need to share this code in a an unlocked form.
 130
 131         """
 132         # increment complete
 133         self._state['complete'] += 1
 134
 135         # Add to the summary dict
 136         assert status in self.SUMMARY_KEYS, \
 137             'Invalid status for logger: {}'.format(status)
 138         self._state['summary'][status] += 1
 139
 140         self._print_summary()
 141         self._state['running'].remove(self.__counter)
 142
 143     def log(self, status):
 144         with self._LOCK:
 145             self._log(status)
 146
 147     def summary(self):
 148         with self._LOCK:
 149             self._print_summary()
 150             self._print('\n')
 151
 152     def _print_summary(self):
 153         """ Print the summary result
 154
 155         this prints '[done/total] {status}', it is a private method hidden from
 156         the children of this class (VerboseLog)
 157
 158         """
 159         assert self._LOCK.locked()
 160
 161         out = '[{done}/{total}] {status} {running}'.format(
 162             done=str(self._state['complete']).zfill(self._pad),
 163             total=str(self._state['total']).zfill(self._pad),
 164             status=', '.join('{0}: {1}'.format(k, v) for k, v in
 165                              sorted(self._state['summary'].items())),
 166             running=''.join('|/-\\'[x % 4] for x in self._state['running'])
 167         )
 168
 169         self._print(out)
 170
 171     def _print(self, out):
 172         """ Shared print method that ensures any bad lines are overwritten """
 173         assert self._LOCK.locked()
 174
 175         # If the new line is shorter than the old one add trailing
 176         # whitespace
 177         pad = self._state['lastlength'] - len(out)
 178
 179         sys.stdout.write(out)
 180         if pad > 0:
 181             sys.stdout.write(' ' * pad)
 182         sys.stdout.write(self._endcode)
 183         sys.stdout.flush()
 184
 185         # Set the length of the line just printed (minus the spaces since
 186         # we don't care if we leave whitespace) so that the next line will
 187         # print extra whitespace if necissary
 188         self._state['lastlength'] = len(out)
 189
 190
 191 class VerboseLog(QuietLog):
 192     """ A more verbose version of the QuietLog
 193
 194     This logger works like the quiet logger, except it doesn't overwrite the
 195     previous line, ever. It also prints an additional line at the start of each
 196     test, which the quite logger doesn't do.
 197
 198     """
 199     def __init__(self, *args, **kwargs):
 200         super(VerboseLog, self).__init__(*args, **kwargs)
 201         self.__name = None    # the name needs to be printed by start and log
 202
 203     def _print(self, out, newline=False):
 204         """ Print to the console, add a newline if necissary
 205
 206         For the verbose logger there are times that one wants both an
 207         overwritten line, and a line that is static. This method adds the
 208         ability to print a newline character at the end of the line.
 209
 210         This is useful for the non-status lines (running: <name>, and <status>:
 211         <name>), since these lines should be be overwritten, but the running
 212         status line should.
 213
 214         """
 215         super(VerboseLog, self)._print(grouptools.format(out))
 216         if newline:
 217             sys.stdout.write('\n')
 218             sys.stdout.flush()
 219
 220     def start(self, name):
 221         """ Print the test that is being run next
 222
 223         This printings a running: <testname> message before the test run
 224         starts.
 225
 226         """
 227         super(VerboseLog, self).start(name)
 228         with self._LOCK:
 229             self._print('running: {}'.format(name), newline=True)
 230             self.__name = name
 231             self._print_summary()
 232
 233     def _log(self, value):
 234         """ Print a message after the test finishes
 235
 236         This method prints <status>: <name>. It also does a little bit of magic
 237         before calling super() to print the status line.
 238
 239         """
 240         self._print('{0}: {1}'.format(value, self.__name), newline=True)
 241
 242         # Set lastlength to 0, this prevents printing needless padding in
 243         # super()
 244         self._state['lastlength'] = 0
 245         super(VerboseLog, self)._log(value)
 246
 247
 248 class DummyLog(BaseLog):
 249     """ A Logger that does nothing """
 250     def __init__(self, state, state_lock):
 251         pass
 252
 253     def start(self, name):
 254         pass
 255
 256     def log(self, status):
 257         pass
 258
 259     def summary(self):
 260         pass
 261
 262
 263 class HTTPLogServer(threading.Thread):
 264     class RequestHandler(BaseHTTPRequestHandler):
 265         INDENT = 4
 266
 267         def do_GET(self):
 268             if self.path == "/summary":
 269                 self.send_response(200)
 270                 self.end_headers()
 271                 with self.server.state_lock:
 272                     status = {
 273                         "complete": self.server.state["complete"],
 274                         "running" : self.server.state["running"],
 275                         "total"   : self.server.state["total"],
 276                         "results" : self.server.state["summary"],
 277                     }
 278                 self.wfile.write(json.dumps(status, indent=self.INDENT))
 279             else:
 280                 self.send_response(404)
 281                 self.end_headers()
 282
 283     def __init__(self, state, state_lock):
 284         super(HTTPLogServer, self).__init__()
 285         port = int(PIGLIT_CONFIG.safe_get("http", "port", fallback=8080))
 286         self._httpd = HTTPServer(("", port), HTTPLogServer.RequestHandler)
 287         self._httpd.state = state
 288         self._httpd.state_lock = state_lock
 289
 290     def run(self):
 291         while True:
 292             with self._httpd.state_lock:
 293                 # stop handling requests after the request for the final results
 294                 if self._httpd.state["complete"] == self._httpd.state["total"]:
 295                     break;
 296             self._httpd.handle_request()
 297
 298
 299 class HTTPLog(BaseLog):
 300     """ A Logger that serves status information over http """
 301
 302     def __init__(self, state, state_lock):
 303         super(HTTPLog, self).__init__(state, state_lock)
 304         self._name = None
 305
 306     def start(self, name):
 307         with self._LOCK:
 308             self._name = name
 309             self._state['running'].append(self._name)
 310
 311     def log(self, status):
 312         with self._LOCK:
 313             self._state['running'].remove(self._name)
 314             self._state['complete'] += 1
 315             assert status in self.SUMMARY_KEYS
 316             self._state['summary'][str(status)] += 1
 317
 318     def summary(self):
 319         pass
 320
 321
 322 class LogManager(object):
 323     """ Creates new log objects
 324
 325     Each of the log objects it creates have two accessible methods: start() and
 326     log(); neither method should return anything, and they must be thread safe.
 327     log() should accept a single argument, which is the status the test
 328     returned. start() should also take a single argument, the name of the test
 329
 330     When the LogManager is initialized it is initialized with an argument which
 331     determines which Log class it will return (they are set via the LOG_MAP
 332     dictionary, which maps string names to class callables), it will return
 333     these as long as it exists.
 334
 335     Arguments:
 336     logger -- a string name of a logger to use
 337     total -- the total number of test to run
 338
 339     """
 340     LOG_MAP = {
 341         'quiet': QuietLog,
 342         'verbose': VerboseLog,
 343         'dummy': DummyLog,
 344         'http': HTTPLog,
 345     }
 346
 347     def __init__(self, logger, total):
 348         assert logger in self.LOG_MAP
 349         self._log = self.LOG_MAP[logger]
 350         self._state = {
 351             'total': total,
 352             'summary': collections.defaultdict(lambda: 0),
 353             'lastlength': 0,
 354             'complete': 0,
 355             'running': [],
 356         }
 357         self._state_lock = threading.Lock()
 358
 359         # start the http server for http logger
 360         if logger == 'http':
 361             self.log_server = HTTPLogServer(self._state, self._state_lock)
 362             self.log_server.start()
 363
 364     def get(self):
 365         """ Return a new log instance """
 366         return self._log(self._state, self._state_lock)