test/py/multiplexed_log.py

   1 # Copyright (c) 2015 Stephen Warren
   2 # Copyright (c) 2015-2016, NVIDIA CORPORATION. All rights reserved.
   3 #
   4 # SPDX-License-Identifier: GPL-2.0
   5
   6 # Generate an HTML-formatted log file containing multiple streams of data,
   7 # each represented in a well-delineated/-structured fashion.
   8
   9 import cgi
  10 import datetime
  11 import os.path
  12 import shutil
  13 import subprocess
  14
  15 mod_dir = os.path.dirname(os.path.abspath(__file__))
  16
  17 class LogfileStream(object):
  18     """A file-like object used to write a single logical stream of data into
  19     a multiplexed log file. Objects of this type should be created by factory
  20     functions in the Logfile class rather than directly."""
  21
  22     def __init__(self, logfile, name, chained_file):
  23         """Initialize a new object.
  24
  25         Args:
  26             logfile: The Logfile object to log to.
  27             name: The name of this log stream.
  28             chained_file: The file-like object to which all stream data should be
  29             logged to in addition to logfile. Can be None.
  30
  31         Returns:
  32             Nothing.
  33         """
  34
  35         self.logfile = logfile
  36         self.name = name
  37         self.chained_file = chained_file
  38
  39     def close(self):
  40         """Dummy function so that this class is "file-like".
  41
  42         Args:
  43             None.
  44
  45         Returns:
  46             Nothing.
  47         """
  48
  49         pass
  50
  51     def write(self, data, implicit=False):
  52         """Write data to the log stream.
  53
  54         Args:
  55             data: The data to write tot he file.
  56             implicit: Boolean indicating whether data actually appeared in the
  57                 stream, or was implicitly generated. A valid use-case is to
  58                 repeat a shell prompt at the start of each separate log
  59                 section, which makes the log sections more readable in
  60                 isolation.
  61
  62         Returns:
  63             Nothing.
  64         """
  65
  66         self.logfile.write(self, data, implicit)
  67         if self.chained_file:
  68             self.chained_file.write(data)
  69
  70     def flush(self):
  71         """Flush the log stream, to ensure correct log interleaving.
  72
  73         Args:
  74             None.
  75
  76         Returns:
  77             Nothing.
  78         """
  79
  80         self.logfile.flush()
  81         if self.chained_file:
  82             self.chained_file.flush()
  83
  84 class RunAndLog(object):
  85     """A utility object used to execute sub-processes and log their output to
  86     a multiplexed log file. Objects of this type should be created by factory
  87     functions in the Logfile class rather than directly."""
  88
  89     def __init__(self, logfile, name, chained_file):
  90         """Initialize a new object.
  91
  92         Args:
  93             logfile: The Logfile object to log to.
  94             name: The name of this log stream or sub-process.
  95             chained_file: The file-like object to which all stream data should
  96                 be logged to in addition to logfile. Can be None.
  97
  98         Returns:
  99             Nothing.
 100         """
 101
 102         self.logfile = logfile
 103         self.name = name
 104         self.chained_file = chained_file
 105         self.output = None
 106         self.exit_status = None
 107
 108     def close(self):
 109         """Clean up any resources managed by this object."""
 110         pass
 111
 112     def run(self, cmd, cwd=None, ignore_errors=False):
 113         """Run a command as a sub-process, and log the results.
 114
 115         The output is available at self.output which can be useful if there is
 116         an exception.
 117
 118         Args:
 119             cmd: The command to execute.
 120             cwd: The directory to run the command in. Can be None to use the
 121                 current directory.
 122             ignore_errors: Indicate whether to ignore errors. If True, the
 123                 function will simply return if the command cannot be executed
 124                 or exits with an error code, otherwise an exception will be
 125                 raised if such problems occur.
 126
 127         Returns:
 128             The output as a string.
 129         """
 130
 131         msg = '+' + ' '.join(cmd) + '\n'
 132         if self.chained_file:
 133             self.chained_file.write(msg)
 134         self.logfile.write(self, msg)
 135
 136         try:
 137             p = subprocess.Popen(cmd, cwd=cwd,
 138                 stdin=None, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
 139             (stdout, stderr) = p.communicate()
 140             output = ''
 141             if stdout:
 142                 if stderr:
 143                     output += 'stdout:\n'
 144                 output += stdout
 145             if stderr:
 146                 if stdout:
 147                     output += 'stderr:\n'
 148                 output += stderr
 149             exit_status = p.returncode
 150             exception = None
 151         except subprocess.CalledProcessError as cpe:
 152             output = cpe.output
 153             exit_status = cpe.returncode
 154             exception = cpe
 155         except Exception as e:
 156             output = ''
 157             exit_status = 0
 158             exception = e
 159         if output and not output.endswith('\n'):
 160             output += '\n'
 161         if exit_status and not exception and not ignore_errors:
 162             exception = Exception('Exit code: ' + str(exit_status))
 163         if exception:
 164             output += str(exception) + '\n'
 165         self.logfile.write(self, output)
 166         if self.chained_file:
 167             self.chained_file.write(output)
 168         self.logfile.timestamp()
 169
 170         # Store the output so it can be accessed if we raise an exception.
 171         self.output = output
 172         self.exit_status = exit_status
 173         if exception:
 174             raise exception
 175         return output
 176
 177 class SectionCtxMgr(object):
 178     """A context manager for Python's "with" statement, which allows a certain
 179     portion of test code to be logged to a separate section of the log file.
 180     Objects of this type should be created by factory functions in the Logfile
 181     class rather than directly."""
 182
 183     def __init__(self, log, marker, anchor):
 184         """Initialize a new object.
 185
 186         Args:
 187             log: The Logfile object to log to.
 188             marker: The name of the nested log section.
 189             anchor: The anchor value to pass to start_section().
 190
 191         Returns:
 192             Nothing.
 193         """
 194
 195         self.log = log
 196         self.marker = marker
 197         self.anchor = anchor
 198
 199     def __enter__(self):
 200         self.anchor = self.log.start_section(self.marker, self.anchor)
 201
 202     def __exit__(self, extype, value, traceback):
 203         self.log.end_section(self.marker)
 204
 205 class Logfile(object):
 206     """Generates an HTML-formatted log file containing multiple streams of
 207     data, each represented in a well-delineated/-structured fashion."""
 208
 209     def __init__(self, fn):
 210         """Initialize a new object.
 211
 212         Args:
 213             fn: The filename to write to.
 214
 215         Returns:
 216             Nothing.
 217         """
 218
 219         self.f = open(fn, 'wt')
 220         self.last_stream = None
 221         self.blocks = []
 222         self.cur_evt = 1
 223         self.anchor = 0
 224         self.timestamp_start = self._get_time()
 225         self.timestamp_prev = self.timestamp_start
 226         self.timestamp_blocks = []
 227
 228         shutil.copy(mod_dir + '/multiplexed_log.css', os.path.dirname(fn))
 229         self.f.write('''\
 230 <html>
 231 <head>
 232 <link rel="stylesheet" type="text/css" href="multiplexed_log.css">
 233 <script src="http://code.jquery.com/jquery.min.js"></script>
 234 <script>
 235 $(document).ready(function () {
 236     // Copy status report HTML to start of log for easy access
 237     sts = $(".block#status_report")[0].outerHTML;
 238     $("tt").prepend(sts);
 239
 240     // Add expand/contract buttons to all block headers
 241     btns = "<span class=\\\"block-expand hidden\\\">[+] </span>" +
 242         "<span class=\\\"block-contract\\\">[-] </span>";
 243     $(".block-header").prepend(btns);
 244
 245     // Pre-contract all blocks which passed, leaving only problem cases
 246     // expanded, to highlight issues the user should look at.
 247     // Only top-level blocks (sections) should have any status
 248     passed_bcs = $(".block-content:has(.status-pass)");
 249     // Some blocks might have multiple status entries (e.g. the status
 250     // report), so take care not to hide blocks with partial success.
 251     passed_bcs = passed_bcs.not(":has(.status-fail)");
 252     passed_bcs = passed_bcs.not(":has(.status-xfail)");
 253     passed_bcs = passed_bcs.not(":has(.status-xpass)");
 254     passed_bcs = passed_bcs.not(":has(.status-skipped)");
 255     // Hide the passed blocks
 256     passed_bcs.addClass("hidden");
 257     // Flip the expand/contract button hiding for those blocks.
 258     bhs = passed_bcs.parent().children(".block-header")
 259     bhs.children(".block-expand").removeClass("hidden");
 260     bhs.children(".block-contract").addClass("hidden");
 261
 262     // Add click handler to block headers.
 263     // The handler expands/contracts the block.
 264     $(".block-header").on("click", function (e) {
 265         var header = $(this);
 266         var content = header.next(".block-content");
 267         var expanded = !content.hasClass("hidden");
 268         if (expanded) {
 269             content.addClass("hidden");
 270             header.children(".block-expand").first().removeClass("hidden");
 271             header.children(".block-contract").first().addClass("hidden");
 272         } else {
 273             header.children(".block-contract").first().removeClass("hidden");
 274             header.children(".block-expand").first().addClass("hidden");
 275             content.removeClass("hidden");
 276         }
 277     });
 278
 279     // When clicking on a link, expand the target block
 280     $("a").on("click", function (e) {
 281         var block = $($(this).attr("href"));
 282         var header = block.children(".block-header");
 283         var content = block.children(".block-content").first();
 284         header.children(".block-contract").first().removeClass("hidden");
 285         header.children(".block-expand").first().addClass("hidden");
 286         content.removeClass("hidden");
 287     });
 288 });
 289 </script>
 290 </head>
 291 <body>
 292 <tt>
 293 ''')
 294
 295     def close(self):
 296         """Close the log file.
 297
 298         After calling this function, no more data may be written to the log.
 299
 300         Args:
 301             None.
 302
 303         Returns:
 304             Nothing.
 305         """
 306
 307         self.f.write('''\
 308 </tt>
 309 </body>
 310 </html>
 311 ''')
 312         self.f.close()
 313
 314     # The set of characters that should be represented as hexadecimal codes in
 315     # the log file.
 316     _nonprint = ('%' + ''.join(chr(c) for c in range(0, 32) if c not in (9, 10)) +
 317                  ''.join(chr(c) for c in range(127, 256)))
 318
 319     def _escape(self, data):
 320         """Render data format suitable for inclusion in an HTML document.
 321
 322         This includes HTML-escaping certain characters, and translating
 323         control characters to a hexadecimal representation.
 324
 325         Args:
 326             data: The raw string data to be escaped.
 327
 328         Returns:
 329             An escaped version of the data.
 330         """
 331
 332         data = data.replace(chr(13), '')
 333         data = ''.join((c in self._nonprint) and ('%%%02x' % ord(c)) or
 334                        c for c in data)
 335         data = cgi.escape(data)
 336         return data
 337
 338     def _terminate_stream(self):
 339         """Write HTML to the log file to terminate the current stream's data.
 340
 341         Args:
 342             None.
 343
 344         Returns:
 345             Nothing.
 346         """
 347
 348         self.cur_evt += 1
 349         if not self.last_stream:
 350             return
 351         self.f.write('</pre>\n')
 352         self.f.write('<div class="stream-trailer block-trailer">End stream: ' +
 353                      self.last_stream.name + '</div>\n')
 354         self.f.write('</div>\n')
 355         self.f.write('</div>\n')
 356         self.last_stream = None
 357
 358     def _note(self, note_type, msg, anchor=None):
 359         """Write a note or one-off message to the log file.
 360
 361         Args:
 362             note_type: The type of note. This must be a value supported by the
 363                 accompanying multiplexed_log.css.
 364             msg: The note/message to log.
 365             anchor: Optional internal link target.
 366
 367         Returns:
 368             Nothing.
 369         """
 370
 371         self._terminate_stream()
 372         self.f.write('<div class="' + note_type + '">\n')
 373         self.f.write('<pre>')
 374         if anchor:
 375             self.f.write('<a href="#%s">' % anchor)
 376         self.f.write(self._escape(msg))
 377         if anchor:
 378             self.f.write('</a>')
 379         self.f.write('\n</pre>\n')
 380         self.f.write('</div>\n')
 381
 382     def start_section(self, marker, anchor=None):
 383         """Begin a new nested section in the log file.
 384
 385         Args:
 386             marker: The name of the section that is starting.
 387             anchor: The value to use for the anchor. If None, a unique value
 388               will be calculated and used
 389
 390         Returns:
 391             Name of the HTML anchor emitted before section.
 392         """
 393
 394         self._terminate_stream()
 395         self.blocks.append(marker)
 396         self.timestamp_blocks.append(self._get_time())
 397         if not anchor:
 398             self.anchor += 1
 399             anchor = str(self.anchor)
 400         blk_path = '/'.join(self.blocks)
 401         self.f.write('<div class="section block" id="' + anchor + '">\n')
 402         self.f.write('<div class="section-header block-header">Section: ' +
 403                      blk_path + '</div>\n')
 404         self.f.write('<div class="section-content block-content">\n')
 405         self.timestamp()
 406
 407         return anchor
 408
 409     def end_section(self, marker):
 410         """Terminate the current nested section in the log file.
 411
 412         This function validates proper nesting of start_section() and
 413         end_section() calls. If a mismatch is found, an exception is raised.
 414
 415         Args:
 416             marker: The name of the section that is ending.
 417
 418         Returns:
 419             Nothing.
 420         """
 421
 422         if (not self.blocks) or (marker != self.blocks[-1]):
 423             raise Exception('Block nesting mismatch: "%s" "%s"' %
 424                             (marker, '/'.join(self.blocks)))
 425         self._terminate_stream()
 426         timestamp_now = self._get_time()
 427         timestamp_section_start = self.timestamp_blocks.pop()
 428         delta_section = timestamp_now - timestamp_section_start
 429         self._note("timestamp",
 430             "TIME: SINCE-SECTION: " + str(delta_section))
 431         blk_path = '/'.join(self.blocks)
 432         self.f.write('<div class="section-trailer block-trailer">' +
 433                      'End section: ' + blk_path + '</div>\n')
 434         self.f.write('</div>\n')
 435         self.f.write('</div>\n')
 436         self.blocks.pop()
 437
 438     def section(self, marker, anchor=None):
 439         """Create a temporary section in the log file.
 440
 441         This function creates a context manager for Python's "with" statement,
 442         which allows a certain portion of test code to be logged to a separate
 443         section of the log file.
 444
 445         Usage:
 446             with log.section("somename"):
 447                 some test code
 448
 449         Args:
 450             marker: The name of the nested section.
 451             anchor: The anchor value to pass to start_section().
 452
 453         Returns:
 454             A context manager object.
 455         """
 456
 457         return SectionCtxMgr(self, marker, anchor)
 458
 459     def error(self, msg):
 460         """Write an error note to the log file.
 461
 462         Args:
 463             msg: A message describing the error.
 464
 465         Returns:
 466             Nothing.
 467         """
 468
 469         self._note("error", msg)
 470
 471     def warning(self, msg):
 472         """Write an warning note to the log file.
 473
 474         Args:
 475             msg: A message describing the warning.
 476
 477         Returns:
 478             Nothing.
 479         """
 480
 481         self._note("warning", msg)
 482
 483     def info(self, msg):
 484         """Write an informational note to the log file.
 485
 486         Args:
 487             msg: An informational message.
 488
 489         Returns:
 490             Nothing.
 491         """
 492
 493         self._note("info", msg)
 494
 495     def action(self, msg):
 496         """Write an action note to the log file.
 497
 498         Args:
 499             msg: A message describing the action that is being logged.
 500
 501         Returns:
 502             Nothing.
 503         """
 504
 505         self._note("action", msg)
 506
 507     def _get_time(self):
 508         return datetime.datetime.now()
 509
 510     def timestamp(self):
 511         """Write a timestamp to the log file.
 512
 513         Args:
 514             None
 515
 516         Returns:
 517             Nothing.
 518         """
 519
 520         timestamp_now = self._get_time()
 521         delta_prev = timestamp_now - self.timestamp_prev
 522         delta_start = timestamp_now - self.timestamp_start
 523         self.timestamp_prev = timestamp_now
 524
 525         self._note("timestamp",
 526             "TIME: NOW: " + timestamp_now.strftime("%Y/%m/%d %H:%M:%S.%f"))
 527         self._note("timestamp",
 528             "TIME: SINCE-PREV: " + str(delta_prev))
 529         self._note("timestamp",
 530             "TIME: SINCE-START: " + str(delta_start))
 531
 532     def status_pass(self, msg, anchor=None):
 533         """Write a note to the log file describing test(s) which passed.
 534
 535         Args:
 536             msg: A message describing the passed test(s).
 537             anchor: Optional internal link target.
 538
 539         Returns:
 540             Nothing.
 541         """
 542
 543         self._note("status-pass", msg, anchor)
 544
 545     def status_skipped(self, msg, anchor=None):
 546         """Write a note to the log file describing skipped test(s).
 547
 548         Args:
 549             msg: A message describing the skipped test(s).
 550             anchor: Optional internal link target.
 551
 552         Returns:
 553             Nothing.
 554         """
 555
 556         self._note("status-skipped", msg, anchor)
 557
 558     def status_xfail(self, msg, anchor=None):
 559         """Write a note to the log file describing xfailed test(s).
 560
 561         Args:
 562             msg: A message describing the xfailed test(s).
 563             anchor: Optional internal link target.
 564
 565         Returns:
 566             Nothing.
 567         """
 568
 569         self._note("status-xfail", msg, anchor)
 570
 571     def status_xpass(self, msg, anchor=None):
 572         """Write a note to the log file describing xpassed test(s).
 573
 574         Args:
 575             msg: A message describing the xpassed test(s).
 576             anchor: Optional internal link target.
 577
 578         Returns:
 579             Nothing.
 580         """
 581
 582         self._note("status-xpass", msg, anchor)
 583
 584     def status_fail(self, msg, anchor=None):
 585         """Write a note to the log file describing failed test(s).
 586
 587         Args:
 588             msg: A message describing the failed test(s).
 589             anchor: Optional internal link target.
 590
 591         Returns:
 592             Nothing.
 593         """
 594
 595         self._note("status-fail", msg, anchor)
 596
 597     def get_stream(self, name, chained_file=None):
 598         """Create an object to log a single stream's data into the log file.
 599
 600         This creates a "file-like" object that can be written to in order to
 601         write a single stream's data to the log file. The implementation will
 602         handle any required interleaving of data (from multiple streams) in
 603         the log, in a way that makes it obvious which stream each bit of data
 604         came from.
 605
 606         Args:
 607             name: The name of the stream.
 608             chained_file: The file-like object to which all stream data should
 609                 be logged to in addition to this log. Can be None.
 610
 611         Returns:
 612             A file-like object.
 613         """
 614
 615         return LogfileStream(self, name, chained_file)
 616
 617     def get_runner(self, name, chained_file=None):
 618         """Create an object that executes processes and logs their output.
 619
 620         Args:
 621             name: The name of this sub-process.
 622             chained_file: The file-like object to which all stream data should
 623                 be logged to in addition to logfile. Can be None.
 624
 625         Returns:
 626             A RunAndLog object.
 627         """
 628
 629         return RunAndLog(self, name, chained_file)
 630
 631     def write(self, stream, data, implicit=False):
 632         """Write stream data into the log file.
 633
 634         This function should only be used by instances of LogfileStream or
 635         RunAndLog.
 636
 637         Args:
 638             stream: The stream whose data is being logged.
 639             data: The data to log.
 640             implicit: Boolean indicating whether data actually appeared in the
 641                 stream, or was implicitly generated. A valid use-case is to
 642                 repeat a shell prompt at the start of each separate log
 643                 section, which makes the log sections more readable in
 644                 isolation.
 645
 646         Returns:
 647             Nothing.
 648         """
 649
 650         if stream != self.last_stream:
 651             self._terminate_stream()
 652             self.f.write('<div class="stream block">\n')
 653             self.f.write('<div class="stream-header block-header">Stream: ' +
 654                          stream.name + '</div>\n')
 655             self.f.write('<div class="stream-content block-content">\n')
 656             self.f.write('<pre>')
 657         if implicit:
 658             self.f.write('<span class="implicit">')
 659         self.f.write(self._escape(data))
 660         if implicit:
 661             self.f.write('</span>')
 662         self.last_stream = stream
 663
 664     def flush(self):
 665         """Flush the log stream, to ensure correct log interleaving.
 666
 667         Args:
 668             None.
 669
 670         Returns:
 671             Nothing.
 672         """
 673
 674         self.f.flush()