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