framework/log.py

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