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