test/py/multiplexed_log.py

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