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