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 = {ord('%')} 318 _nonprint.update({c for c in range(0, 32) if c not in (9, 10)}) 319 _nonprint.update({c for c in range(127, 256)}) 320 321 def _escape(self, data): 322 """Render data format suitable for inclusion in an HTML document. 323 324 This includes HTML-escaping certain characters, and translating 325 control characters to a hexadecimal representation. 326 327 Args: 328 data: The raw string data to be escaped. 329 330 Returns: 331 An escaped version of the data. 332 """ 333 334 data = data.replace(chr(13), '') 335 data = ''.join((ord(c) in self._nonprint) and ('%%%02x' % ord(c)) or 336 c for c in data) 337 data = cgi.escape(data) 338 return data 339 340 def _terminate_stream(self): 341 """Write HTML to the log file to terminate the current stream's data. 342 343 Args: 344 None. 345 346 Returns: 347 Nothing. 348 """ 349 350 self.cur_evt += 1 351 if not self.last_stream: 352 return 353 self.f.write('</pre>\n') 354 self.f.write('<div class="stream-trailer block-trailer">End stream: ' + 355 self.last_stream.name + '</div>\n') 356 self.f.write('</div>\n') 357 self.f.write('</div>\n') 358 self.last_stream = None 359 360 def _note(self, note_type, msg, anchor=None): 361 """Write a note or one-off message to the log file. 362 363 Args: 364 note_type: The type of note. This must be a value supported by the 365 accompanying multiplexed_log.css. 366 msg: The note/message to log. 367 anchor: Optional internal link target. 368 369 Returns: 370 Nothing. 371 """ 372 373 self._terminate_stream() 374 self.f.write('<div class="' + note_type + '">\n') 375 self.f.write('<pre>') 376 if anchor: 377 self.f.write('<a href="#%s">' % anchor) 378 self.f.write(self._escape(msg)) 379 if anchor: 380 self.f.write('</a>') 381 self.f.write('\n</pre>\n') 382 self.f.write('</div>\n') 383 384 def start_section(self, marker, anchor=None): 385 """Begin a new nested section in the log file. 386 387 Args: 388 marker: The name of the section that is starting. 389 anchor: The value to use for the anchor. If None, a unique value 390 will be calculated and used 391 392 Returns: 393 Name of the HTML anchor emitted before section. 394 """ 395 396 self._terminate_stream() 397 self.blocks.append(marker) 398 self.timestamp_blocks.append(self._get_time()) 399 if not anchor: 400 self.anchor += 1 401 anchor = str(self.anchor) 402 blk_path = '/'.join(self.blocks) 403 self.f.write('<div class="section block" id="' + anchor + '">\n') 404 self.f.write('<div class="section-header block-header">Section: ' + 405 blk_path + '</div>\n') 406 self.f.write('<div class="section-content block-content">\n') 407 self.timestamp() 408 409 return anchor 410 411 def end_section(self, marker): 412 """Terminate the current nested section in the log file. 413 414 This function validates proper nesting of start_section() and 415 end_section() calls. If a mismatch is found, an exception is raised. 416 417 Args: 418 marker: The name of the section that is ending. 419 420 Returns: 421 Nothing. 422 """ 423 424 if (not self.blocks) or (marker != self.blocks[-1]): 425 raise Exception('Block nesting mismatch: "%s" "%s"' % 426 (marker, '/'.join(self.blocks))) 427 self._terminate_stream() 428 timestamp_now = self._get_time() 429 timestamp_section_start = self.timestamp_blocks.pop() 430 delta_section = timestamp_now - timestamp_section_start 431 self._note("timestamp", 432 "TIME: SINCE-SECTION: " + str(delta_section)) 433 blk_path = '/'.join(self.blocks) 434 self.f.write('<div class="section-trailer block-trailer">' + 435 'End section: ' + blk_path + '</div>\n') 436 self.f.write('</div>\n') 437 self.f.write('</div>\n') 438 self.blocks.pop() 439 440 def section(self, marker, anchor=None): 441 """Create a temporary section in the log file. 442 443 This function creates a context manager for Python's "with" statement, 444 which allows a certain portion of test code to be logged to a separate 445 section of the log file. 446 447 Usage: 448 with log.section("somename"): 449 some test code 450 451 Args: 452 marker: The name of the nested section. 453 anchor: The anchor value to pass to start_section(). 454 455 Returns: 456 A context manager object. 457 """ 458 459 return SectionCtxMgr(self, marker, anchor) 460 461 def error(self, msg): 462 """Write an error note to the log file. 463 464 Args: 465 msg: A message describing the error. 466 467 Returns: 468 Nothing. 469 """ 470 471 self._note("error", msg) 472 473 def warning(self, msg): 474 """Write an warning note to the log file. 475 476 Args: 477 msg: A message describing the warning. 478 479 Returns: 480 Nothing. 481 """ 482 483 self.seen_warning = True 484 self._note("warning", msg) 485 486 def get_and_reset_warning(self): 487 """Get and reset the log warning flag. 488 489 Args: 490 None 491 492 Returns: 493 Whether a warning was seen since the last call. 494 """ 495 496 ret = self.seen_warning 497 self.seen_warning = False 498 return ret 499 500 def info(self, msg): 501 """Write an informational note to the log file. 502 503 Args: 504 msg: An informational message. 505 506 Returns: 507 Nothing. 508 """ 509 510 self._note("info", msg) 511 512 def action(self, msg): 513 """Write an action note to the log file. 514 515 Args: 516 msg: A message describing the action that is being logged. 517 518 Returns: 519 Nothing. 520 """ 521 522 self._note("action", msg) 523 524 def _get_time(self): 525 return datetime.datetime.now() 526 527 def timestamp(self): 528 """Write a timestamp to the log file. 529 530 Args: 531 None 532 533 Returns: 534 Nothing. 535 """ 536 537 timestamp_now = self._get_time() 538 delta_prev = timestamp_now - self.timestamp_prev 539 delta_start = timestamp_now - self.timestamp_start 540 self.timestamp_prev = timestamp_now 541 542 self._note("timestamp", 543 "TIME: NOW: " + timestamp_now.strftime("%Y/%m/%d %H:%M:%S.%f")) 544 self._note("timestamp", 545 "TIME: SINCE-PREV: " + str(delta_prev)) 546 self._note("timestamp", 547 "TIME: SINCE-START: " + str(delta_start)) 548 549 def status_pass(self, msg, anchor=None): 550 """Write a note to the log file describing test(s) which passed. 551 552 Args: 553 msg: A message describing the passed test(s). 554 anchor: Optional internal link target. 555 556 Returns: 557 Nothing. 558 """ 559 560 self._note("status-pass", msg, anchor) 561 562 def status_warning(self, msg, anchor=None): 563 """Write a note to the log file describing test(s) which passed. 564 565 Args: 566 msg: A message describing the passed test(s). 567 anchor: Optional internal link target. 568 569 Returns: 570 Nothing. 571 """ 572 573 self._note("status-warning", msg, anchor) 574 575 def status_skipped(self, msg, anchor=None): 576 """Write a note to the log file describing skipped test(s). 577 578 Args: 579 msg: A message describing the skipped test(s). 580 anchor: Optional internal link target. 581 582 Returns: 583 Nothing. 584 """ 585 586 self._note("status-skipped", msg, anchor) 587 588 def status_xfail(self, msg, anchor=None): 589 """Write a note to the log file describing xfailed test(s). 590 591 Args: 592 msg: A message describing the xfailed test(s). 593 anchor: Optional internal link target. 594 595 Returns: 596 Nothing. 597 """ 598 599 self._note("status-xfail", msg, anchor) 600 601 def status_xpass(self, msg, anchor=None): 602 """Write a note to the log file describing xpassed test(s). 603 604 Args: 605 msg: A message describing the xpassed test(s). 606 anchor: Optional internal link target. 607 608 Returns: 609 Nothing. 610 """ 611 612 self._note("status-xpass", msg, anchor) 613 614 def status_fail(self, msg, anchor=None): 615 """Write a note to the log file describing failed test(s). 616 617 Args: 618 msg: A message describing the failed test(s). 619 anchor: Optional internal link target. 620 621 Returns: 622 Nothing. 623 """ 624 625 self._note("status-fail", msg, anchor) 626 627 def get_stream(self, name, chained_file=None): 628 """Create an object to log a single stream's data into the log file. 629 630 This creates a "file-like" object that can be written to in order to 631 write a single stream's data to the log file. The implementation will 632 handle any required interleaving of data (from multiple streams) in 633 the log, in a way that makes it obvious which stream each bit of data 634 came from. 635 636 Args: 637 name: The name of the stream. 638 chained_file: The file-like object to which all stream data should 639 be logged to in addition to this log. Can be None. 640 641 Returns: 642 A file-like object. 643 """ 644 645 return LogfileStream(self, name, chained_file) 646 647 def get_runner(self, name, chained_file=None): 648 """Create an object that executes processes and logs their output. 649 650 Args: 651 name: The name of this sub-process. 652 chained_file: The file-like object to which all stream data should 653 be logged to in addition to logfile. Can be None. 654 655 Returns: 656 A RunAndLog object. 657 """ 658 659 return RunAndLog(self, name, chained_file) 660 661 def write(self, stream, data, implicit=False): 662 """Write stream data into the log file. 663 664 This function should only be used by instances of LogfileStream or 665 RunAndLog. 666 667 Args: 668 stream: The stream whose data is being logged. 669 data: The data to log. 670 implicit: Boolean indicating whether data actually appeared in the 671 stream, or was implicitly generated. A valid use-case is to 672 repeat a shell prompt at the start of each separate log 673 section, which makes the log sections more readable in 674 isolation. 675 676 Returns: 677 Nothing. 678 """ 679 680 if stream != self.last_stream: 681 self._terminate_stream() 682 self.f.write('<div class="stream block">\n') 683 self.f.write('<div class="stream-header block-header">Stream: ' + 684 stream.name + '</div>\n') 685 self.f.write('<div class="stream-content block-content">\n') 686 self.f.write('<pre>') 687 if implicit: 688 self.f.write('<span class="implicit">') 689 self.f.write(self._escape(data)) 690 if implicit: 691 self.f.write('</span>') 692 self.last_stream = stream 693 694 def flush(self): 695 """Flush the log stream, to ensure correct log interleaving. 696 697 Args: 698 None. 699 700 Returns: 701 Nothing. 702 """ 703 704 self.f.flush() 705