test/py/multiplexed_log.py

   1 # SPDX-License-Identifier: GPL-2.0
   2 # Copyright (c) 2015 Stephen Warren
   3 # Copyright (c) 2015-2016, NVIDIA CORPORATION. All rights reserved.
   4
   5 # Generate an HTML-formatted log file containing multiple streams of data,
   6 # each represented in a well-delineated/-structured fashion.
   7
   8 import cgi
   9 import datetime
  10 import os.path
  11 import shutil
  12 import subprocess
  13
  14 mod_dir = os.path.dirname(os.path.abspath(__file__))
  15
  16 class LogfileStream(object):
  17     """A file-like object used to write a single logical stream of data into
  18     a multiplexed log file. Objects of this type should be created by factory
  19     functions in the Logfile class rather than directly."""
  20
  21     def __init__(self, logfile, name, chained_file):
  22         """Initialize a new object.
  23
  24         Args:
  25             logfile: The Logfile object to log to.
  26             name: The name of this log stream.
  27             chained_file: The file-like object to which all stream data should be
  28             logged to in addition to logfile. Can be None.
  29
  30         Returns:
  31             Nothing.
  32         """
  33
  34         self.logfile = logfile
  35         self.name = name
  36         self.chained_file = chained_file
  37
  38     def close(self):
  39         """Dummy function so that this class is "file-like".
  40
  41         Args:
  42             None.
  43
  44         Returns:
  45             Nothing.
  46         """
  47
  48         pass
  49
  50     def write(self, data, implicit=False):
  51         """Write data to the log stream.
  52
  53         Args:
  54             data: The data to write tot he file.
  55             implicit: Boolean indicating whether data actually appeared in the
  56                 stream, or was implicitly generated. A valid use-case is to
  57                 repeat a shell prompt at the start of each separate log
  58                 section, which makes the log sections more readable in
  59                 isolation.
  60
  61         Returns:
  62             Nothing.
  63         """
  64
  65         self.logfile.write(self, data, implicit)
  66         if self.chained_file:
  67             self.chained_file.write(data)
  68
  69     def flush(self):
  70         """Flush the log stream, to ensure correct log interleaving.
  71
  72         Args:
  73             None.
  74
  75         Returns:
  76             Nothing.
  77         """
  78
  79         self.logfile.flush()
  80         if self.chained_file:
  81             self.chained_file.flush()
  82
  83 class RunAndLog(object):
  84     """A utility object used to execute sub-processes and log their output to
  85     a multiplexed log file. Objects of this type should be created by factory
  86     functions in the Logfile class rather than directly."""
  87
  88     def __init__(self, logfile, name, chained_file):
  89         """Initialize a new object.
  90
  91         Args:
  92             logfile: The Logfile object to log to.
  93             name: The name of this log stream or sub-process.
  94             chained_file: The file-like object to which all stream data should
  95                 be logged to in addition to logfile. Can be None.
  96
  97         Returns:
  98             Nothing.
  99         """
 100
 101         self.logfile = logfile
 102         self.name = name
 103         self.chained_file = chained_file
 104         self.output = None
 105         self.exit_status = None
 106
 107     def close(self):
 108         """Clean up any resources managed by this object."""
 109         pass
 110
 111     def run(self, cmd, cwd=None, ignore_errors=False):
 112         """Run a command as a sub-process, and log the results.
 113
 114         The output is available at self.output which can be useful if there is
 115         an exception.
 116
 117         Args:
 118             cmd: The command to execute.
 119             cwd: The directory to run the command in. Can be None to use the
 120                 current directory.
 121             ignore_errors: Indicate whether to ignore errors. If True, the
 122                 function will simply return if the command cannot be executed
 123                 or exits with an error code, otherwise an exception will be
 124                 raised if such problems occur.
 125
 126         Returns:
 127             The output as a string.
 128         """
 129
 130         msg = '+' + ' '.join(cmd) + '\n'
 131         if self.chained_file:
 132             self.chained_file.write(msg)
 133         self.logfile.write(self, msg)
 134
 135         try:
 136             p = subprocess.Popen(cmd, cwd=cwd,
 137                 stdin=None, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
 138             (stdout, stderr) = p.communicate()
 139             output = ''
 140             if stdout:
 141                 if stderr:
 142                     output += 'stdout:\n'
 143                 output += stdout
 144             if stderr:
 145                 if stdout:
 146                     output += 'stderr:\n'
 147                 output += stderr
 148             exit_status = p.returncode
 149             exception = None
 150         except subprocess.CalledProcessError as cpe:
 151             output = cpe.output
 152             exit_status = cpe.returncode
 153             exception = cpe
 154         except Exception as e:
 155             output = ''
 156             exit_status = 0
 157             exception = e
 158         if output and not output.endswith('\n'):
 159             output += '\n'
 160         if exit_status and not exception and not ignore_errors:
 161             exception = Exception('Exit code: ' + str(exit_status))
 162         if exception:
 163             output += str(exception) + '\n'
 164         self.logfile.write(self, output)
 165         if self.chained_file:
 166             self.chained_file.write(output)
 167         self.logfile.timestamp()
 168
 169         # Store the output so it can be accessed if we raise an exception.
 170         self.output = output
 171         self.exit_status = exit_status
 172         if exception:
 173             raise exception
 174         return output
 175
 176 class SectionCtxMgr(object):
 177     """A context manager for Python's "with" statement, which allows a certain
 178     portion of test code to be logged to a separate section of the log file.
 179     Objects of this type should be created by factory functions in the Logfile
 180     class rather than directly."""
 181
 182     def __init__(self, log, marker, anchor):
 183         """Initialize a new object.
 184
 185         Args:
 186             log: The Logfile object to log to.
 187             marker: The name of the nested log section.
 188             anchor: The anchor value to pass to start_section().
 189
 190         Returns:
 191             Nothing.
 192         """
 193
 194         self.log = log
 195         self.marker = marker
 196         self.anchor = anchor
 197
 198     def __enter__(self):
 199         self.anchor = self.log.start_section(self.marker, self.anchor)
 200
 201     def __exit__(self, extype, value, traceback):
 202         self.log.end_section(self.marker)
 203
 204 class Logfile(object):
 205     """Generates an HTML-formatted log file containing multiple streams of
 206     data, each represented in a well-delineated/-structured fashion."""
 207
 208     def __init__(self, fn):
 209         """Initialize a new object.
 210
 211         Args:
 212             fn: The filename to write to.
 213
 214         Returns:
 215             Nothing.
 216         """
 217
 218         self.f = open(fn, 'wt')
 219         self.last_stream = None
 220         self.blocks = []
 221         self.cur_evt = 1
 222         self.anchor = 0
 223         self.timestamp_start = self._get_time()
 224         self.timestamp_prev = self.timestamp_start
 225         self.timestamp_blocks = []
 226         self.seen_warning = False
 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     passed_bcs = passed_bcs.not(":has(.status-warning)");
 256     // Hide the passed blocks
 257     passed_bcs.addClass("hidden");
 258     // Flip the expand/contract button hiding for those blocks.
 259     bhs = passed_bcs.parent().children(".block-header")
 260     bhs.children(".block-expand").removeClass("hidden");
 261     bhs.children(".block-contract").addClass("hidden");
 262
 263     // Add click handler to block headers.
 264     // The handler expands/contracts the block.
 265     $(".block-header").on("click", function (e) {
 266         var header = $(this);
 267         var content = header.next(".block-content");
 268         var expanded = !content.hasClass("hidden");
 269         if (expanded) {
 270             content.addClass("hidden");
 271             header.children(".block-expand").first().removeClass("hidden");
 272             header.children(".block-contract").first().addClass("hidden");
 273         } else {
 274             header.children(".block-contract").first().removeClass("hidden");
 275             header.children(".block-expand").first().addClass("hidden");
 276             content.removeClass("hidden");
 277         }
 278     });
 279
 280     // When clicking on a link, expand the target block
 281     $("a").on("click", function (e) {
 282         var block = $($(this).attr("href"));
 283         var header = block.children(".block-header");
 284         var content = block.children(".block-content").first();
 285         header.children(".block-contract").first().removeClass("hidden");
 286         header.children(".block-expand").first().addClass("hidden");
 287         content.removeClass("hidden");
 288     });
 289 });
 290 </script>
 291 </head>
 292 <body>
 293 <tt>
 294 ''')
 295
 296     def close(self):
 297         """Close the log file.
 298
 299         After calling this function, no more data may be written to the log.
 300
 301         Args:
 302             None.
 303
 304         Returns:
 305             Nothing.
 306         """
 307
 308         self.f.write('''\
 309 </tt>
 310 </body>
 311 </html>
 312 ''')
 313         self.f.close()
 314
 315     # The set of characters that should be represented as hexadecimal codes in
 316     # the log file.
 317     _nonprint = {ord('%')}
 318     _nonprint.update({c for c in range(0, 32) if c not in (9, 10)})
 319     _nonprint.update({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((ord(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()