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