git.sur5r.net Git - u-boot/blob - test/py/multiplexed_log.py

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