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         self.seen_warning = False
 228
 229         shutil.copy(mod_dir + '/multiplexed_log.css', os.path.dirname(fn))
 230         self.f.write('''\
 231 <html>
 232 <head>
 233 <link rel="stylesheet" type="text/css" href="multiplexed_log.css">
 234 <script src="http://code.jquery.com/jquery.min.js"></script>
 235 <script>
 236 $(document).ready(function () {
 237     // Copy status report HTML to start of log for easy access
 238     sts = $(".block#status_report")[0].outerHTML;
 239     $("tt").prepend(sts);
 240
 241     // Add expand/contract buttons to all block headers
 242     btns = "<span class=\\\"block-expand hidden\\\">[+] </span>" +
 243         "<span class=\\\"block-contract\\\">[-] </span>";
 244     $(".block-header").prepend(btns);
 245
 246     // Pre-contract all blocks which passed, leaving only problem cases
 247     // expanded, to highlight issues the user should look at.
 248     // Only top-level blocks (sections) should have any status
 249     passed_bcs = $(".block-content:has(.status-pass)");
 250     // Some blocks might have multiple status entries (e.g. the status
 251     // report), so take care not to hide blocks with partial success.
 252     passed_bcs = passed_bcs.not(":has(.status-fail)");
 253     passed_bcs = passed_bcs.not(":has(.status-xfail)");
 254     passed_bcs = passed_bcs.not(":has(.status-xpass)");
 255     passed_bcs = passed_bcs.not(":has(.status-skipped)");
 256     passed_bcs = passed_bcs.not(":has(.status-warning)");
 257     // Hide the passed blocks
 258     passed_bcs.addClass("hidden");
 259     // Flip the expand/contract button hiding for those blocks.
 260     bhs = passed_bcs.parent().children(".block-header")
 261     bhs.children(".block-expand").removeClass("hidden");
 262     bhs.children(".block-contract").addClass("hidden");
 263
 264     // Add click handler to block headers.
 265     // The handler expands/contracts the block.
 266     $(".block-header").on("click", function (e) {
 267         var header = $(this);
 268         var content = header.next(".block-content");
 269         var expanded = !content.hasClass("hidden");
 270         if (expanded) {
 271             content.addClass("hidden");
 272             header.children(".block-expand").first().removeClass("hidden");
 273             header.children(".block-contract").first().addClass("hidden");
 274         } else {
 275             header.children(".block-contract").first().removeClass("hidden");
 276             header.children(".block-expand").first().addClass("hidden");
 277             content.removeClass("hidden");
 278         }
 279     });
 280
 281     // When clicking on a link, expand the target block
 282     $("a").on("click", function (e) {
 283         var block = $($(this).attr("href"));
 284         var header = block.children(".block-header");
 285         var content = block.children(".block-content").first();
 286         header.children(".block-contract").first().removeClass("hidden");
 287         header.children(".block-expand").first().addClass("hidden");
 288         content.removeClass("hidden");
 289     });
 290 });
 291 </script>
 292 </head>
 293 <body>
 294 <tt>
 295 ''')
 296
 297     def close(self):
 298         """Close the log file.
 299
 300         After calling this function, no more data may be written to the log.
 301
 302         Args:
 303             None.
 304
 305         Returns:
 306             Nothing.
 307         """
 308
 309         self.f.write('''\
 310 </tt>
 311 </body>
 312 </html>
 313 ''')
 314         self.f.close()
 315
 316     # The set of characters that should be represented as hexadecimal codes in
 317     # the log file.
 318     _nonprint = ('%' + ''.join(chr(c) for c in range(0, 32) if c not in (9, 10)) +
 319                  ''.join(chr(c) for c in range(127, 256)))
 320
 321     def _escape(self, data):
 322         """Render data format suitable for inclusion in an HTML document.
 323
 324         This includes HTML-escaping certain characters, and translating
 325         control characters to a hexadecimal representation.
 326
 327         Args:
 328             data: The raw string data to be escaped.
 329
 330         Returns:
 331             An escaped version of the data.
 332         """
 333
 334         data = data.replace(chr(13), '')
 335         data = ''.join((c in self._nonprint) and ('%%%02x' % ord(c)) or
 336                        c for c in data)
 337         data = cgi.escape(data)
 338         return data
 339
 340     def _terminate_stream(self):
 341         """Write HTML to the log file to terminate the current stream's data.
 342
 343         Args:
 344             None.
 345
 346         Returns:
 347             Nothing.
 348         """
 349
 350         self.cur_evt += 1
 351         if not self.last_stream:
 352             return
 353         self.f.write('</pre>\n')
 354         self.f.write('<div class="stream-trailer block-trailer">End stream: ' +
 355                      self.last_stream.name + '</div>\n')
 356         self.f.write('</div>\n')
 357         self.f.write('</div>\n')
 358         self.last_stream = None
 359
 360     def _note(self, note_type, msg, anchor=None):
 361         """Write a note or one-off message to the log file.
 362
 363         Args:
 364             note_type: The type of note. This must be a value supported by the
 365                 accompanying multiplexed_log.css.
 366             msg: The note/message to log.
 367             anchor: Optional internal link target.
 368
 369         Returns:
 370             Nothing.
 371         """
 372
 373         self._terminate_stream()
 374         self.f.write('<div class="' + note_type + '">\n')
 375         self.f.write('<pre>')
 376         if anchor:
 377             self.f.write('<a href="#%s">' % anchor)
 378         self.f.write(self._escape(msg))
 379         if anchor:
 380             self.f.write('</a>')
 381         self.f.write('\n</pre>\n')
 382         self.f.write('</div>\n')
 383
 384     def start_section(self, marker, anchor=None):
 385         """Begin a new nested section in the log file.
 386
 387         Args:
 388             marker: The name of the section that is starting.
 389             anchor: The value to use for the anchor. If None, a unique value
 390               will be calculated and used
 391
 392         Returns:
 393             Name of the HTML anchor emitted before section.
 394         """
 395
 396         self._terminate_stream()
 397         self.blocks.append(marker)
 398         self.timestamp_blocks.append(self._get_time())
 399         if not anchor:
 400             self.anchor += 1
 401             anchor = str(self.anchor)
 402         blk_path = '/'.join(self.blocks)
 403         self.f.write('<div class="section block" id="' + anchor + '">\n')
 404         self.f.write('<div class="section-header block-header">Section: ' +
 405                      blk_path + '</div>\n')
 406         self.f.write('<div class="section-content block-content">\n')
 407         self.timestamp()
 408
 409         return anchor
 410
 411     def end_section(self, marker):
 412         """Terminate the current nested section in the log file.
 413
 414         This function validates proper nesting of start_section() and
 415         end_section() calls. If a mismatch is found, an exception is raised.
 416
 417         Args:
 418             marker: The name of the section that is ending.
 419
 420         Returns:
 421             Nothing.
 422         """
 423
 424         if (not self.blocks) or (marker != self.blocks[-1]):
 425             raise Exception('Block nesting mismatch: "%s" "%s"' %
 426                             (marker, '/'.join(self.blocks)))
 427         self._terminate_stream()
 428         timestamp_now = self._get_time()
 429         timestamp_section_start = self.timestamp_blocks.pop()
 430         delta_section = timestamp_now - timestamp_section_start
 431         self._note("timestamp",
 432             "TIME: SINCE-SECTION: " + str(delta_section))
 433         blk_path = '/'.join(self.blocks)
 434         self.f.write('<div class="section-trailer block-trailer">' +
 435                      'End section: ' + blk_path + '</div>\n')
 436         self.f.write('</div>\n')
 437         self.f.write('</div>\n')
 438         self.blocks.pop()
 439
 440     def section(self, marker, anchor=None):
 441         """Create a temporary section in the log file.
 442
 443         This function creates a context manager for Python's "with" statement,
 444         which allows a certain portion of test code to be logged to a separate
 445         section of the log file.
 446
 447         Usage:
 448             with log.section("somename"):
 449                 some test code
 450
 451         Args:
 452             marker: The name of the nested section.
 453             anchor: The anchor value to pass to start_section().
 454
 455         Returns:
 456             A context manager object.
 457         """
 458
 459         return SectionCtxMgr(self, marker, anchor)
 460
 461     def error(self, msg):
 462         """Write an error note to the log file.
 463
 464         Args:
 465             msg: A message describing the error.
 466
 467         Returns:
 468             Nothing.
 469         """
 470
 471         self._note("error", msg)
 472
 473     def warning(self, msg):
 474         """Write an warning note to the log file.
 475
 476         Args:
 477             msg: A message describing the warning.
 478
 479         Returns:
 480             Nothing.
 481         """
 482
 483         self.seen_warning = True
 484         self._note("warning", msg)
 485
 486     def get_and_reset_warning(self):
 487         """Get and reset the log warning flag.
 488
 489         Args:
 490             None
 491
 492         Returns:
 493             Whether a warning was seen since the last call.
 494         """
 495
 496         ret = self.seen_warning
 497         self.seen_warning = False
 498         return ret
 499
 500     def info(self, msg):
 501         """Write an informational note to the log file.
 502
 503         Args:
 504             msg: An informational message.
 505
 506         Returns:
 507             Nothing.
 508         """
 509
 510         self._note("info", msg)
 511
 512     def action(self, msg):
 513         """Write an action note to the log file.
 514
 515         Args:
 516             msg: A message describing the action that is being logged.
 517
 518         Returns:
 519             Nothing.
 520         """
 521
 522         self._note("action", msg)
 523
 524     def _get_time(self):
 525         return datetime.datetime.now()
 526
 527     def timestamp(self):
 528         """Write a timestamp to the log file.
 529
 530         Args:
 531             None
 532
 533         Returns:
 534             Nothing.
 535         """
 536
 537         timestamp_now = self._get_time()
 538         delta_prev = timestamp_now - self.timestamp_prev
 539         delta_start = timestamp_now - self.timestamp_start
 540         self.timestamp_prev = timestamp_now
 541
 542         self._note("timestamp",
 543             "TIME: NOW: " + timestamp_now.strftime("%Y/%m/%d %H:%M:%S.%f"))
 544         self._note("timestamp",
 545             "TIME: SINCE-PREV: " + str(delta_prev))
 546         self._note("timestamp",
 547             "TIME: SINCE-START: " + str(delta_start))
 548
 549     def status_pass(self, msg, anchor=None):
 550         """Write a note to the log file describing test(s) which passed.
 551
 552         Args:
 553             msg: A message describing the passed test(s).
 554             anchor: Optional internal link target.
 555
 556         Returns:
 557             Nothing.
 558         """
 559
 560         self._note("status-pass", msg, anchor)
 561
 562     def status_warning(self, msg, anchor=None):
 563         """Write a note to the log file describing test(s) which passed.
 564
 565         Args:
 566             msg: A message describing the passed test(s).
 567             anchor: Optional internal link target.
 568
 569         Returns:
 570             Nothing.
 571         """
 572
 573         self._note("status-warning", msg, anchor)
 574
 575     def status_skipped(self, msg, anchor=None):
 576         """Write a note to the log file describing skipped test(s).
 577
 578         Args:
 579             msg: A message describing the skipped test(s).
 580             anchor: Optional internal link target.
 581
 582         Returns:
 583             Nothing.
 584         """
 585
 586         self._note("status-skipped", msg, anchor)
 587
 588     def status_xfail(self, msg, anchor=None):
 589         """Write a note to the log file describing xfailed test(s).
 590
 591         Args:
 592             msg: A message describing the xfailed test(s).
 593             anchor: Optional internal link target.
 594
 595         Returns:
 596             Nothing.
 597         """
 598
 599         self._note("status-xfail", msg, anchor)
 600
 601     def status_xpass(self, msg, anchor=None):
 602         """Write a note to the log file describing xpassed test(s).
 603
 604         Args:
 605             msg: A message describing the xpassed test(s).
 606             anchor: Optional internal link target.
 607
 608         Returns:
 609             Nothing.
 610         """
 611
 612         self._note("status-xpass", msg, anchor)
 613
 614     def status_fail(self, msg, anchor=None):
 615         """Write a note to the log file describing failed test(s).
 616
 617         Args:
 618             msg: A message describing the failed test(s).
 619             anchor: Optional internal link target.
 620
 621         Returns:
 622             Nothing.
 623         """
 624
 625         self._note("status-fail", msg, anchor)
 626
 627     def get_stream(self, name, chained_file=None):
 628         """Create an object to log a single stream's data into the log file.
 629
 630         This creates a "file-like" object that can be written to in order to
 631         write a single stream's data to the log file. The implementation will
 632         handle any required interleaving of data (from multiple streams) in
 633         the log, in a way that makes it obvious which stream each bit of data
 634         came from.
 635
 636         Args:
 637             name: The name of the stream.
 638             chained_file: The file-like object to which all stream data should
 639                 be logged to in addition to this log. Can be None.
 640
 641         Returns:
 642             A file-like object.
 643         """
 644
 645         return LogfileStream(self, name, chained_file)
 646
 647     def get_runner(self, name, chained_file=None):
 648         """Create an object that executes processes and logs their output.
 649
 650         Args:
 651             name: The name of this sub-process.
 652             chained_file: The file-like object to which all stream data should
 653                 be logged to in addition to logfile. Can be None.
 654
 655         Returns:
 656             A RunAndLog object.
 657         """
 658
 659         return RunAndLog(self, name, chained_file)
 660
 661     def write(self, stream, data, implicit=False):
 662         """Write stream data into the log file.
 663
 664         This function should only be used by instances of LogfileStream or
 665         RunAndLog.
 666
 667         Args:
 668             stream: The stream whose data is being logged.
 669             data: The data to log.
 670             implicit: Boolean indicating whether data actually appeared in the
 671                 stream, or was implicitly generated. A valid use-case is to
 672                 repeat a shell prompt at the start of each separate log
 673                 section, which makes the log sections more readable in
 674                 isolation.
 675
 676         Returns:
 677             Nothing.
 678         """
 679
 680         if stream != self.last_stream:
 681             self._terminate_stream()
 682             self.f.write('<div class="stream block">\n')
 683             self.f.write('<div class="stream-header block-header">Stream: ' +
 684                          stream.name + '</div>\n')
 685             self.f.write('<div class="stream-content block-content">\n')
 686             self.f.write('<pre>')
 687         if implicit:
 688             self.f.write('<span class="implicit">')
 689         self.f.write(self._escape(data))
 690         if implicit:
 691             self.f.write('</span>')
 692         self.last_stream = stream
 693
 694     def flush(self):
 695         """Flush the log stream, to ensure correct log interleaving.
 696
 697         Args:
 698             None.
 699
 700         Returns:
 701             Nothing.
 702         """
 703
 704         self.f.flush()