1# Lint as: python2, python3 2""" 3Autotest has some surprisingly complicated logging behaviour. 4 5Managers allow you to define logging contexts, which define a set of rules on 6how to handle stdout/stderr. The niceness that you get by going through the 7logging_manager for this is that you can push/pop these contexts. So if you 8wish to temporarily change how logging works, this gives you that mechanism. 9 10Most of this file is actually setting up for a confusing 11fork-for-a-logging-subprocess ordeal that's better explained as 12 13 normal python logging 14 ^ 15 | 16 +--------+ | 17 |AUTOSERV| +---+---+ 18 | +------stdout---->+LOGGING| 19 | fork() | +---+---+ 20 ++------++ ^ 21 | | | 22 +--------+ +--------+ stdout 23 | | | 24 +---------+--------+ +--------+---------+ | 25 | AUTOSERV | | AUTOSERV | | 26 | | | | | 27 ++----------------++ ++----------------++ | 28 || test || || test || | 29 || || || ||---+ 30 ||logging.info('')|| ||logging.info('')|| 31 |------------------| |------------------| 32 +------------------+ +------------------+ 33 34Each top-level box is a process. When autoserv starts up, it'll fork off a 35logging subprocess, and set its stdout/stderr fd's to the subprocess's stdin. 36When we fork to create the processes that will run the test code, they inherit 37this. As do any processes they themselves fork and exec (such as shelling out 38to some command). This isn't the nicest, as it involves closing and dup'ing 39over stdout/stderr, but it does make sure that the whole process tree logs to 40python logging in a very consistent way. 41""" 42 43 44import fcntl 45import logging 46import os 47import signal 48import six 49import sys 50import time 51import warnings 52 53# primary public APIs 54 55def configure_logging(logging_config, **kwargs): 56 """ 57 Configure the logging module using the specific configuration object, which 58 should be an instance of logging_config.LoggingConfig (usually of a 59 subclass). Any keyword args will be passed to the object's 60 configure_logging() method. 61 62 Every entry point should call this method at application startup. 63 """ 64 LoggingManager.logging_config_object = logging_config 65 logging_config.configure_logging(**kwargs) 66 67 68def get_logging_manager(manage_stdout_and_stderr=False, redirect_fds=False): 69 """ 70 Create a LoggingManager that's managing sys.stdout and sys.stderr. 71 72 Every entry point that wants to capture stdout/stderr and/or use 73 LoggingManager to manage a stack of destinations should call this method 74 at application startup. 75 """ 76 if redirect_fds: 77 manager = FdRedirectionLoggingManager() 78 else: 79 manager = LoggingManager() 80 if manage_stdout_and_stderr: 81 manager.manage_stdout() 82 manager.manage_stderr() 83 return manager 84 85 86# implementation follows 87 88logger = logging.getLogger() 89 90 91def _current_handlers(): 92 return set(logger.handlers) 93 94 95_caller_code_to_skip_in_logging_stack = set() 96 97 98def do_not_report_as_logging_caller(func): 99 """Decorator to annotate functions we will tell logging not to log.""" 100 # These are not the droids you are looking for. 101 # You may go about your business. 102 _caller_code_to_skip_in_logging_stack.add(func.__code__) 103 return func 104 105 106# Copied from Python 2.4 logging/__init__.py Logger.findCaller and enhanced. 107# The logging code remains the same and compatible with this monkey patching 108# through at least Python version 2.6.2. 109def _logging_manager_aware_logger__find_caller(unused): 110 """ 111 Find the stack frame of the caller so that we can note the source 112 file name, line number and function name. 113 """ 114 f = sys._getframe(2).f_back 115 rv = "(unknown file)", 0, "(unknown function)" 116 while hasattr(f, "f_code"): 117 co = f.f_code 118 filename = os.path.normcase(co.co_filename) 119 if filename == logging._srcfile: 120 f = f.f_back 121 continue 122 ### START additional code. 123 if co in _caller_code_to_skip_in_logging_stack: 124 f = f.f_back 125 continue 126 ### END additional code. 127 rv = (filename, f.f_lineno, co.co_name) 128 break 129 return rv 130 131 132if sys.version_info[:2] > (2, 7): 133 warnings.warn('This module has not been reviewed for Python %s' % 134 sys.version) 135 136 137# Monkey patch our way around logging's design... 138_original_logger__find_caller = logging.Logger.findCaller 139# Do not overwrite in Python 3 and on. It breaks the "<module>:<line num>|" 140# formatting in Python 3. 141if six.PY2: 142 logging.Logger.findCaller = _logging_manager_aware_logger__find_caller 143 144 145 146class LoggingFile(object): 147 """ 148 File-like object that will receive messages pass them to the logging 149 infrastructure in an appropriate way. 150 """ 151 152 # This object is used to replace stdout and stderr, but doesn't expose 153 # the same interface as a file object. To work around the most troublesome 154 # part of the API, |fileno()|, we need to be able to provide a fake fd that 155 # can pass basic checks. 156 _fake_fds = os.pipe() 157 158 def __init__(self, prefix='', level=logging.DEBUG): 159 """ 160 @param prefix - The prefix for each line logged by this object. 161 """ 162 self._prefix = prefix 163 self._level = level 164 self._buffer = [] 165 166 167 @do_not_report_as_logging_caller 168 def write(self, data): 169 """" 170 Writes data only if it constitutes a whole line. If it's not the case, 171 store it in a buffer and wait until we have a complete line. 172 @param data - Raw data (a string) that will be processed. 173 """ 174 # splitlines() discards a trailing blank line, so use split() instead 175 data_lines = data.split('\n') 176 if len(data_lines) > 1: 177 self._buffer.append(data_lines[0]) 178 self._flush_buffer() 179 for line in data_lines[1:-1]: 180 self._log_line(line) 181 if data_lines[-1]: 182 self._buffer.append(data_lines[-1]) 183 184 185 @do_not_report_as_logging_caller 186 def _log_line(self, line): 187 """ 188 Passes lines of output to the logging module. 189 """ 190 logging.log(self._level, self._prefix + line) 191 192 193 @do_not_report_as_logging_caller 194 def _flush_buffer(self): 195 if self._buffer: 196 self._log_line(''.join(self._buffer)) 197 self._buffer = [] 198 199 200 @do_not_report_as_logging_caller 201 def flush(self): 202 self._flush_buffer() 203 204 205 @do_not_report_as_logging_caller 206 def isatty(self): 207 return False 208 209 210 @do_not_report_as_logging_caller 211 def fileno(self): 212 # We return the read end of the pipe here becauase if we return the 213 # write end, one can make the reasonable assumption that writing to the 214 # fd is the same as stdout.write(). As we aren't reading from the other 215 # end of the pipe, writing to this fd should be an error. 216 return self._fake_fds[0] 217 218 219class _StreamManager(object): 220 """ 221 Redirects all output for some output stream (normally stdout or stderr) to 222 the logging module by replacing the file objects with a new LoggingFile 223 that calls logging.log(). 224 """ 225 def __init__(self, stream, level, stream_setter): 226 """ 227 @param stream: stream object to manage 228 @param level: level at which data written to the stream will be logged 229 @param stream_setter: function accepting a stream object that will 230 replace the given stream in its original location. 231 """ 232 self._stream = stream 233 self._level = level 234 self._stream_setter = stream_setter 235 self._logging_stream = None 236 237 238 def _replace_with_logger(self): 239 self._logging_stream = LoggingFile(level=self._level) 240 self._stream_setter(self._logging_stream) 241 242 243 def _restore_stream(self): 244 self._stream_setter(self._stream) 245 246 247 def flush(self): 248 self._logging_stream.flush() 249 250 251 def start_logging(self): 252 """Start directing the stream to the logging module.""" 253 self._replace_with_logger() 254 255 256 def stop_logging(self): 257 """Restore the stream to its original settings.""" 258 self._restore_stream() 259 260 261 def on_push_context(self, context): 262 """ 263 Called when the logging manager is about to push a new context onto the 264 stack and has changed logging settings. The StreamHandler can modify 265 the context to be saved before returning. 266 """ 267 pass 268 269 270 def on_restore_context(self, context): 271 """ 272 Called when the logging manager is restoring a previous context. 273 """ 274 pass 275 276 277 278class LoggingManager(object): 279 """ 280 Manages a stack of logging configurations, allowing clients to conveniently 281 add and remove logging destinations. Also keeps a list of StreamManagers 282 to easily direct streams into the logging module. 283 """ 284 285 STREAM_MANAGER_CLASS = _StreamManager 286 287 logging_config_object = None 288 289 def __init__(self): 290 """ 291 This class should not ordinarily be constructed directly (other than in 292 tests). Use the module-global factory method get_logging_manager() 293 instead. 294 """ 295 if self.logging_config_object is None: 296 raise RuntimeError('You must call configure_logging() before this') 297 298 # _context_stack holds a stack of context dicts. Each context dict 299 # contains: 300 # * old_handlers: list of registered logging Handlers 301 # contexts may also be extended by _StreamHandlers 302 self._context_stack = [] 303 self._streams = [] 304 self._started = False 305 306 307 def manage_stream(self, stream, level, stream_setter): 308 """ 309 Tells this manager to manage the given stream. All data written to the 310 stream will be directed to the logging module instead. Must be called 311 before start_logging(). 312 313 @param stream: stream to manage 314 @param level: level to log data written to this stream 315 @param stream_setter: function to set the stream to a new object 316 """ 317 if self._started: 318 raise RuntimeError('You must call this before start_logging()') 319 self._streams.append(self.STREAM_MANAGER_CLASS(stream, level, 320 stream_setter)) 321 322 323 def _sys_stream_setter(self, stream_name): 324 assert stream_name in ('stdout', 'stderr'), stream_name 325 def set_stream(file_object): 326 setattr(sys, stream_name, file_object) 327 return set_stream 328 329 330 def manage_stdout(self): 331 self.manage_stream(sys.stdout, logging.INFO, 332 self._sys_stream_setter('stdout')) 333 334 335 def manage_stderr(self): 336 self.manage_stream(sys.stderr, self.logging_config_object.stderr_level, 337 self._sys_stream_setter('stderr')) 338 339 340 def start_logging(self): 341 """ 342 Begin capturing output to the logging module. 343 """ 344 for stream_manager in self._streams: 345 stream_manager.start_logging() 346 self._started = True 347 348 349 def stop_logging(self): 350 """ 351 Restore output to its original state. 352 """ 353 while self._context_stack: 354 self._pop_context() 355 356 for stream_manager in self._streams: 357 stream_manager.stop_logging() 358 359 self._started = False 360 361 362 def _clear_all_handlers(self): 363 for handler in _current_handlers(): 364 logger.removeHandler(handler) 365 366 367 def _get_context(self): 368 return {'old_handlers': _current_handlers()} 369 370 371 def _push_context(self, context): 372 for stream_manager in self._streams: 373 stream_manager.on_push_context(context) 374 self._context_stack.append(context) 375 376 377 def _flush_all_streams(self): 378 for stream_manager in self._streams: 379 stream_manager.flush() 380 381 382 def _add_log_handlers(self, add_handlers_fn): 383 """ 384 Modify the logging module's registered handlers and push a new context 385 onto the stack. 386 @param add_handlers_fn: function to modify the registered logging 387 handlers. Accepts a context dictionary which may be modified. 388 """ 389 self._flush_all_streams() 390 context = self._get_context() 391 392 add_handlers_fn(context) 393 394 self._push_context(context) 395 396 397 class _TaggingFormatter(logging.Formatter): 398 """ 399 Delegates to a given formatter, but prefixes each line of output with a 400 tag. 401 """ 402 def __init__(self, base_formatter, tag): 403 self.base_formatter = base_formatter 404 prefix = tag + ' : ' 405 self._fmt = base_formatter._fmt.replace('%(message)s', 406 prefix + '%(message)s') 407 self.datefmt = base_formatter.datefmt 408 409 410 def _add_tagging_formatter(self, tag): 411 for handler in _current_handlers(): 412 tagging_formatter = self._TaggingFormatter(handler.formatter, tag) 413 handler.setFormatter(tagging_formatter) 414 415 416 def _do_redirect(self, stream=None, filename=None, level=None, 417 clear_other_handlers=False): 418 """ 419 @param clear_other_handlers - if true, clear out all other logging 420 handlers. 421 """ 422 assert bool(stream) != bool(filename) # xor 423 if not self._started: 424 raise RuntimeError('You must call start_logging() before this') 425 426 def add_handler(context): 427 if clear_other_handlers: 428 self._clear_all_handlers() 429 430 if stream: 431 handler = self.logging_config_object.add_stream_handler(stream) 432 else: 433 handler = self.logging_config_object.add_file_handler(filename) 434 435 if level: 436 handler.setLevel(level) 437 438 self._add_log_handlers(add_handler) 439 440 441 def redirect(self, filename): 442 """Redirect output to the specified file""" 443 self._do_redirect(filename=filename, clear_other_handlers=True) 444 445 446 def redirect_to_stream(self, stream): 447 """Redirect output to the given stream""" 448 self._do_redirect(stream=stream, clear_other_handlers=True) 449 450 451 def tee_redirect(self, filename, level=None): 452 """Tee output to the specified file""" 453 self._do_redirect(filename=filename, level=level) 454 455 456 def tee_redirect_to_stream(self, stream): 457 """Tee output to the given stream""" 458 self._do_redirect(stream=stream) 459 460 461 def tee_redirect_debug_dir(self, debug_dir, log_name=None, tag=None): 462 """ 463 Tee output to a full new set of debug logs in the given directory. 464 """ 465 def add_handlers(context): 466 if tag: 467 self._add_tagging_formatter(tag) 468 context['tag_added'] = True 469 self.logging_config_object.add_debug_file_handlers( 470 debug_dir, log_name=log_name) 471 self._add_log_handlers(add_handlers) 472 473 474 def _restore_context(self, context): 475 for stream_handler in self._streams: 476 stream_handler.on_restore_context(context) 477 478 # restore logging handlers 479 old_handlers = context['old_handlers'] 480 for handler in _current_handlers() - old_handlers: 481 handler.close() 482 self._clear_all_handlers() 483 for handler in old_handlers: 484 logger.addHandler(handler) 485 486 if 'tag_added' in context: 487 for handler in _current_handlers(): 488 tagging_formatter = handler.formatter 489 handler.setFormatter(tagging_formatter.base_formatter) 490 491 492 def _pop_context(self): 493 self._flush_all_streams() 494 context = self._context_stack.pop() 495 self._restore_context(context) 496 497 498 def undo_redirect(self): 499 """ 500 Undo the last redirection (that hasn't yet been undone). 501 502 If any subprocesses have been launched since the redirection was 503 performed, they must have ended by the time this is called. Otherwise, 504 this will hang waiting for the logging subprocess to end. 505 """ 506 if not self._context_stack: 507 raise RuntimeError('No redirects to undo') 508 self._pop_context() 509 510 511 def restore(self): 512 """ 513 Same as undo_redirect(). For backwards compatibility with 514 fd_stack. 515 """ 516 self.undo_redirect() 517 518 519class _FdRedirectionStreamManager(_StreamManager): 520 """ 521 Like StreamManager, but also captures output from subprocesses by modifying 522 the underlying file descriptors. 523 524 For the underlying file descriptors, we spawn a subprocess that writes all 525 input to the logging module, and we point the FD to that subprocess. As a 526 result, every time we redirect output we need to spawn a new subprocess to 527 pick up the new logging settings (without disturbing any existing processes 528 using the old logging subprocess). 529 530 If, one day, we could get all code using utils.run() and friends to launch 531 subprocesses, we'd no longer need to handle raw FD output, and we could 532 get rid of all this business with subprocesses. Another option would be 533 to capture all stray output to a single, separate destination. 534 """ 535 536 WAITPID_TIMEOUT_S = 5 537 WAITPID_SAMPLE_TIME_S = 0.1 538 539 def __init__(self, stream, level, stream_setter): 540 if not hasattr(stream, 'fileno'): 541 # with fake, in-process file objects, subprocess output won't be 542 # captured. this should never happen in normal use, since the 543 # factory methods will only pass sys.stdout and sys.stderr. 544 raise ValueError("FdRedirectionLoggingManager won't work with " 545 "streams that aren't backed by file " 546 "descriptors") 547 548 super(_FdRedirectionStreamManager, self).__init__(stream, level, 549 stream_setter) 550 self._fd = stream.fileno() 551 self._fd_copy_stream = None 552 553 554 def _point_stream_handlers_to_copy(self): 555 """ 556 point logging StreamHandlers that point to this stream to a safe 557 copy of the underlying FD. otherwise, StreamHandler output will go 558 to the logging subprocess, effectively getting doubly logged. 559 """ 560 fd_copy = os.dup(self._fd) 561 self._fd_copy_stream = os.fdopen(fd_copy, 'w') 562 self._redirect_logging_stream_handlers(self._stream, 563 self._fd_copy_stream) 564 565 566 def _restore_stream_handlers(self): 567 """ point logging StreamHandlers back to the original FD """ 568 self._redirect_logging_stream_handlers(self._fd_copy_stream, 569 self._stream) 570 self._fd_copy_stream.close() 571 572 573 def _redirect_logging_stream_handlers(self, old_stream, new_stream): 574 """ 575 Redirect all configured logging StreamHandlers pointing to 576 old_stream to point to new_stream instead. 577 """ 578 for handler in _current_handlers(): 579 points_to_stream = (isinstance(handler, logging.StreamHandler) and 580 hasattr(handler.stream, 'fileno') and 581 handler.stream.fileno() == old_stream.fileno()) 582 if points_to_stream: 583 logger.removeHandler(handler) 584 handler.close() # doesn't close the stream, just the handler 585 586 new_handler = logging.StreamHandler(new_stream) 587 new_handler.setLevel(handler.level) 588 new_handler.setFormatter(handler.formatter) 589 for log_filter in handler.filters: 590 new_handler.addFilter(log_filter) 591 logger.addHandler(new_handler) 592 593 594 def start_logging(self): 595 super(_FdRedirectionStreamManager, self).start_logging() 596 self._point_stream_handlers_to_copy() 597 598 599 def stop_logging(self): 600 super(_FdRedirectionStreamManager, self).stop_logging() 601 self._restore_stream_handlers() 602 603 604 def _spawn_logging_subprocess(self): 605 """ 606 Spawn a subprocess to log all input to the logging module with the 607 current settings, and direct output to it. 608 """ 609 read_end, write_end = os.pipe() 610 pid = os.fork() 611 if pid: # parent 612 os.close(read_end) 613 os.dup2(write_end, self._fd) # point FD to the subprocess 614 os.close(write_end) 615 fd_flags = fcntl.fcntl(self._fd, fcntl.F_GETFD) 616 fcntl.fcntl(self._fd, fcntl.F_SETFD, 617 fd_flags | fcntl.FD_CLOEXEC) 618 return pid 619 else: # child 620 try: 621 os.close(write_end) 622 # ensure this subprocess doesn't hold any pipes to others 623 os.close(1) 624 os.close(2) 625 self._run_logging_subprocess(read_end) # never returns 626 except: 627 # don't let exceptions in the child escape 628 try: 629 logging.exception('Logging subprocess died:') 630 finally: 631 os._exit(1) 632 633 634 def _run_logging_subprocess(self, read_fd): 635 """ 636 Always run from a subprocess. Read from read_fd and write to the 637 logging module until EOF. 638 """ 639 # A SIGTERM will be issued by the main process if it believes this 640 # subprocess to the stuck. In that case, simply exit with status 1. 641 # See below for pending TODO on how to remove this. 642 signal.signal(signal.SIGTERM, lambda signum, stack: os._exit(1)) 643 input_file = os.fdopen(read_fd, 'r') 644 for line in iter(input_file.readline, ''): 645 logging.log(self._level, line.rstrip('\n')) 646 logging.debug('Logging subprocess finished') 647 os._exit(0) 648 649 650 def _context_id(self): 651 return '%s_context' % id(self) 652 653 654 def on_push_context(self, context): 655 # adds a context dict for this stream, $id_context, with the following: 656 # * old_fd: FD holding a copy of the managed FD before launching a new 657 # subprocess. 658 # * child_pid: PID of the logging subprocess launched 659 fd_copy = os.dup(self._fd) 660 child_pid = self._spawn_logging_subprocess() 661 my_context = {'old_fd': fd_copy, 'child_pid': child_pid} 662 context[self._context_id()] = my_context 663 664 665 def on_restore_context(self, context): 666 my_context = context[self._context_id()] 667 668 # shut down subprocess 669 child_pid = my_context['child_pid'] 670 try: 671 os.close(self._fd) 672 # TODO(crbug.com/970115): remove this work-around in favor of 673 # a clean waitpid(child_pid, 0) once the issue described in the 674 # bug is root caused and resolved. 675 end = time.time() + self.WAITPID_TIMEOUT_S 676 while time.time() < end: 677 if os.waitpid(child_pid, os.WNOHANG) != (0, 0): 678 break 679 time.sleep(self.WAITPID_SAMPLE_TIME_S) 680 else: 681 # After timeout the process still hasn't finished. Send a 682 # SIGTERM as it's likely stuck. 683 os.kill(child_pid, signal.SIGTERM) 684 logging.exception('Ended up killing logging subprocess at %s.', 685 child_pid) 686 except OSError: 687 logging.exception('Failed to cleanly shutdown logging subprocess:') 688 689 # restore previous FD 690 old_fd = my_context['old_fd'] 691 os.dup2(old_fd, self._fd) 692 os.close(old_fd) 693 694 695class FdRedirectionLoggingManager(LoggingManager): 696 """ 697 A simple extension of LoggingManager to use FdRedirectionStreamManagers, 698 so that managed streams have their underlying FDs redirected. 699 """ 700 701 STREAM_MANAGER_CLASS = _FdRedirectionStreamManager 702 703 def start_logging(self): 704 super(FdRedirectionLoggingManager, self).start_logging() 705 # spawn the initial logging subprocess 706 self._push_context(self._get_context()) 707 708 709 def undo_redirect(self): 710 # len == 1 would mean only start_logging() had been called (but no 711 # redirects had occurred) 712 if len(self._context_stack) < 2: 713 raise RuntimeError('No redirects to undo') 714 super(FdRedirectionLoggingManager, self).undo_redirect() 715