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