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""" 6Generate an HTML-formatted log file containing multiple streams of data, 7each represented in a well-delineated/-structured fashion. 8""" 9 10import datetime 11import html 12import os.path 13import shutil 14import subprocess 15 16mod_dir = os.path.dirname(os.path.abspath(__file__)) 17 18class 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 86class 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 186class 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 214class 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() 715