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