| """ |
| Autotest has some surprisingly complicated logging behaviour. |
| |
| Managers allow you to define logging contexts, which define a set of rules on |
| how to handle stdout/stderr. The niceness that you get by going through the |
| logging_manager for this is that you can push/pop these contexts. So if you |
| wish to temporarily change how logging works, this gives you that mechanism. |
| |
| Most of this file is actually setting up for a confusing |
| fork-for-a-logging-subprocess ordeal that's better explained as |
| |
| normal python logging |
| ^ |
| | |
| +--------+ | |
| |AUTOSERV| +---+---+ |
| | +------stdout---->+LOGGING| |
| | fork() | +---+---+ |
| ++------++ ^ |
| | | | |
| +--------+ +--------+ stdout |
| | | | |
| +---------+--------+ +--------+---------+ | |
| | AUTOSERV | | AUTOSERV | | |
| | | | | | |
| ++----------------++ ++----------------++ | |
| || test || || test || | |
| || || || ||---+ |
| ||logging.info('')|| ||logging.info('')|| |
| |------------------| |------------------| |
| +------------------+ +------------------+ |
| |
| Each top-level box is a process. When autoserv starts up, it'll fork off a |
| logging subprocess, and set its stdout/stderr fd's to the subprocess's stdin. |
| When we fork to create the processes that will run the test code, they inherit |
| this. As do any processes they themselves fork and exec (such as shelling out |
| to some command). This isn't the nicest, as it involves closing and dup'ing |
| over stdout/stderr, but it does make sure that the whole process tree logs to |
| python logging in a very consistent way. |
| """ |
| |
| |
| import fcntl, logging, os, signal, sys, time, warnings |
| |
| # primary public APIs |
| |
| def configure_logging(logging_config, **kwargs): |
| """ |
| Configure the logging module using the specific configuration object, which |
| should be an instance of logging_config.LoggingConfig (usually of a |
| subclass). Any keyword args will be passed to the object's |
| configure_logging() method. |
| |
| Every entry point should call this method at application startup. |
| """ |
| LoggingManager.logging_config_object = logging_config |
| logging_config.configure_logging(**kwargs) |
| |
| |
| def get_logging_manager(manage_stdout_and_stderr=False, redirect_fds=False): |
| """ |
| Create a LoggingManager that's managing sys.stdout and sys.stderr. |
| |
| Every entry point that wants to capture stdout/stderr and/or use |
| LoggingManager to manage a stack of destinations should call this method |
| at application startup. |
| """ |
| if redirect_fds: |
| manager = FdRedirectionLoggingManager() |
| else: |
| manager = LoggingManager() |
| if manage_stdout_and_stderr: |
| manager.manage_stdout() |
| manager.manage_stderr() |
| return manager |
| |
| |
| # implementation follows |
| |
| logger = logging.getLogger() |
| |
| |
| def _current_handlers(): |
| return set(logger.handlers) |
| |
| |
| _caller_code_to_skip_in_logging_stack = set() |
| |
| |
| def do_not_report_as_logging_caller(func): |
| """Decorator to annotate functions we will tell logging not to log.""" |
| # These are not the droids you are looking for. |
| # You may go about your business. |
| _caller_code_to_skip_in_logging_stack.add(func.func_code) |
| return func |
| |
| |
| # Copied from Python 2.4 logging/__init__.py Logger.findCaller and enhanced. |
| # The logging code remains the same and compatible with this monkey patching |
| # through at least Python version 2.6.2. |
| def _logging_manager_aware_logger__find_caller(unused): |
| """ |
| Find the stack frame of the caller so that we can note the source |
| file name, line number and function name. |
| """ |
| f = sys._getframe(2).f_back |
| rv = "(unknown file)", 0, "(unknown function)" |
| while hasattr(f, "f_code"): |
| co = f.f_code |
| filename = os.path.normcase(co.co_filename) |
| if filename == logging._srcfile: |
| f = f.f_back |
| continue |
| ### START additional code. |
| if co in _caller_code_to_skip_in_logging_stack: |
| f = f.f_back |
| continue |
| ### END additional code. |
| rv = (filename, f.f_lineno, co.co_name) |
| break |
| return rv |
| |
| |
| if sys.version_info[:2] > (2, 7): |
| warnings.warn('This module has not been reviewed for Python %s' % |
| sys.version) |
| |
| |
| # Monkey patch our way around logging's design... |
| _original_logger__find_caller = logging.Logger.findCaller |
| logging.Logger.findCaller = _logging_manager_aware_logger__find_caller |
| |
| |
| class LoggingFile(object): |
| """ |
| File-like object that will receive messages pass them to the logging |
| infrastructure in an appropriate way. |
| """ |
| |
| # This object is used to replace stdout and stderr, but doesn't expose |
| # the same interface as a file object. To work around the most troublesome |
| # part of the API, |fileno()|, we need to be able to provide a fake fd that |
| # can pass basic checks. |
| _fake_fds = os.pipe() |
| |
| def __init__(self, prefix='', level=logging.DEBUG): |
| """ |
| @param prefix - The prefix for each line logged by this object. |
| """ |
| self._prefix = prefix |
| self._level = level |
| self._buffer = [] |
| |
| |
| @do_not_report_as_logging_caller |
| def write(self, data): |
| """" |
| Writes data only if it constitutes a whole line. If it's not the case, |
| store it in a buffer and wait until we have a complete line. |
| @param data - Raw data (a string) that will be processed. |
| """ |
| # splitlines() discards a trailing blank line, so use split() instead |
| data_lines = data.split('\n') |
| if len(data_lines) > 1: |
| self._buffer.append(data_lines[0]) |
| self._flush_buffer() |
| for line in data_lines[1:-1]: |
| self._log_line(line) |
| if data_lines[-1]: |
| self._buffer.append(data_lines[-1]) |
| |
| |
| @do_not_report_as_logging_caller |
| def _log_line(self, line): |
| """ |
| Passes lines of output to the logging module. |
| """ |
| logging.log(self._level, self._prefix + line) |
| |
| |
| @do_not_report_as_logging_caller |
| def _flush_buffer(self): |
| if self._buffer: |
| self._log_line(''.join(self._buffer)) |
| self._buffer = [] |
| |
| |
| @do_not_report_as_logging_caller |
| def flush(self): |
| self._flush_buffer() |
| |
| |
| @do_not_report_as_logging_caller |
| def isatty(self): |
| return False |
| |
| |
| @do_not_report_as_logging_caller |
| def fileno(self): |
| # We return the read end of the pipe here becauase if we return the |
| # write end, one can make the reasonable assumption that writing to the |
| # fd is the same as stdout.write(). As we aren't reading from the other |
| # end of the pipe, writing to this fd should be an error. |
| return self._fake_fds[0] |
| |
| |
| class _StreamManager(object): |
| """ |
| Redirects all output for some output stream (normally stdout or stderr) to |
| the logging module by replacing the file objects with a new LoggingFile |
| that calls logging.log(). |
| """ |
| def __init__(self, stream, level, stream_setter): |
| """ |
| @param stream: stream object to manage |
| @param level: level at which data written to the stream will be logged |
| @param stream_setter: function accepting a stream object that will |
| replace the given stream in its original location. |
| """ |
| self._stream = stream |
| self._level = level |
| self._stream_setter = stream_setter |
| self._logging_stream = None |
| |
| |
| def _replace_with_logger(self): |
| self._logging_stream = LoggingFile(level=self._level) |
| self._stream_setter(self._logging_stream) |
| |
| |
| def _restore_stream(self): |
| self._stream_setter(self._stream) |
| |
| |
| def flush(self): |
| self._logging_stream.flush() |
| |
| |
| def start_logging(self): |
| """Start directing the stream to the logging module.""" |
| self._replace_with_logger() |
| |
| |
| def stop_logging(self): |
| """Restore the stream to its original settings.""" |
| self._restore_stream() |
| |
| |
| def on_push_context(self, context): |
| """ |
| Called when the logging manager is about to push a new context onto the |
| stack and has changed logging settings. The StreamHandler can modify |
| the context to be saved before returning. |
| """ |
| pass |
| |
| |
| def on_restore_context(self, context): |
| """ |
| Called when the logging manager is restoring a previous context. |
| """ |
| pass |
| |
| |
| |
| class LoggingManager(object): |
| """ |
| Manages a stack of logging configurations, allowing clients to conveniently |
| add and remove logging destinations. Also keeps a list of StreamManagers |
| to easily direct streams into the logging module. |
| """ |
| |
| STREAM_MANAGER_CLASS = _StreamManager |
| |
| logging_config_object = None |
| |
| def __init__(self): |
| """ |
| This class should not ordinarily be constructed directly (other than in |
| tests). Use the module-global factory method get_logging_manager() |
| instead. |
| """ |
| if self.logging_config_object is None: |
| raise RuntimeError('You must call configure_logging() before this') |
| |
| # _context_stack holds a stack of context dicts. Each context dict |
| # contains: |
| # * old_handlers: list of registered logging Handlers |
| # contexts may also be extended by _StreamHandlers |
| self._context_stack = [] |
| self._streams = [] |
| self._started = False |
| |
| |
| def manage_stream(self, stream, level, stream_setter): |
| """ |
| Tells this manager to manage the given stream. All data written to the |
| stream will be directed to the logging module instead. Must be called |
| before start_logging(). |
| |
| @param stream: stream to manage |
| @param level: level to log data written to this stream |
| @param stream_setter: function to set the stream to a new object |
| """ |
| if self._started: |
| raise RuntimeError('You must call this before start_logging()') |
| self._streams.append(self.STREAM_MANAGER_CLASS(stream, level, |
| stream_setter)) |
| |
| |
| def _sys_stream_setter(self, stream_name): |
| assert stream_name in ('stdout', 'stderr'), stream_name |
| def set_stream(file_object): |
| setattr(sys, stream_name, file_object) |
| return set_stream |
| |
| |
| def manage_stdout(self): |
| self.manage_stream(sys.stdout, logging.INFO, |
| self._sys_stream_setter('stdout')) |
| |
| |
| def manage_stderr(self): |
| self.manage_stream(sys.stderr, self.logging_config_object.stderr_level, |
| self._sys_stream_setter('stderr')) |
| |
| |
| def start_logging(self): |
| """ |
| Begin capturing output to the logging module. |
| """ |
| for stream_manager in self._streams: |
| stream_manager.start_logging() |
| self._started = True |
| |
| |
| def stop_logging(self): |
| """ |
| Restore output to its original state. |
| """ |
| while self._context_stack: |
| self._pop_context() |
| |
| for stream_manager in self._streams: |
| stream_manager.stop_logging() |
| |
| self._started = False |
| |
| |
| def _clear_all_handlers(self): |
| for handler in _current_handlers(): |
| logger.removeHandler(handler) |
| |
| |
| def _get_context(self): |
| return {'old_handlers': _current_handlers()} |
| |
| |
| def _push_context(self, context): |
| for stream_manager in self._streams: |
| stream_manager.on_push_context(context) |
| self._context_stack.append(context) |
| |
| |
| def _flush_all_streams(self): |
| for stream_manager in self._streams: |
| stream_manager.flush() |
| |
| |
| def _add_log_handlers(self, add_handlers_fn): |
| """ |
| Modify the logging module's registered handlers and push a new context |
| onto the stack. |
| @param add_handlers_fn: function to modify the registered logging |
| handlers. Accepts a context dictionary which may be modified. |
| """ |
| self._flush_all_streams() |
| context = self._get_context() |
| |
| add_handlers_fn(context) |
| |
| self._push_context(context) |
| |
| |
| class _TaggingFormatter(logging.Formatter): |
| """ |
| Delegates to a given formatter, but prefixes each line of output with a |
| tag. |
| """ |
| def __init__(self, base_formatter, tag): |
| self.base_formatter = base_formatter |
| prefix = tag + ' : ' |
| self._fmt = base_formatter._fmt.replace('%(message)s', |
| prefix + '%(message)s') |
| self.datefmt = base_formatter.datefmt |
| |
| |
| def _add_tagging_formatter(self, tag): |
| for handler in _current_handlers(): |
| tagging_formatter = self._TaggingFormatter(handler.formatter, tag) |
| handler.setFormatter(tagging_formatter) |
| |
| |
| def _do_redirect(self, stream=None, filename=None, level=None, |
| clear_other_handlers=False): |
| """ |
| @param clear_other_handlers - if true, clear out all other logging |
| handlers. |
| """ |
| assert bool(stream) != bool(filename) # xor |
| if not self._started: |
| raise RuntimeError('You must call start_logging() before this') |
| |
| def add_handler(context): |
| if clear_other_handlers: |
| self._clear_all_handlers() |
| |
| if stream: |
| handler = self.logging_config_object.add_stream_handler(stream) |
| else: |
| handler = self.logging_config_object.add_file_handler(filename) |
| |
| if level: |
| handler.setLevel(level) |
| |
| self._add_log_handlers(add_handler) |
| |
| |
| def redirect(self, filename): |
| """Redirect output to the specified file""" |
| self._do_redirect(filename=filename, clear_other_handlers=True) |
| |
| |
| def redirect_to_stream(self, stream): |
| """Redirect output to the given stream""" |
| self._do_redirect(stream=stream, clear_other_handlers=True) |
| |
| |
| def tee_redirect(self, filename, level=None): |
| """Tee output to the specified file""" |
| self._do_redirect(filename=filename, level=level) |
| |
| |
| def tee_redirect_to_stream(self, stream): |
| """Tee output to the given stream""" |
| self._do_redirect(stream=stream) |
| |
| |
| def tee_redirect_debug_dir(self, debug_dir, log_name=None, tag=None): |
| """ |
| Tee output to a full new set of debug logs in the given directory. |
| """ |
| def add_handlers(context): |
| if tag: |
| self._add_tagging_formatter(tag) |
| context['tag_added'] = True |
| self.logging_config_object.add_debug_file_handlers( |
| debug_dir, log_name=log_name) |
| self._add_log_handlers(add_handlers) |
| |
| |
| def _restore_context(self, context): |
| for stream_handler in self._streams: |
| stream_handler.on_restore_context(context) |
| |
| # restore logging handlers |
| old_handlers = context['old_handlers'] |
| for handler in _current_handlers() - old_handlers: |
| handler.close() |
| self._clear_all_handlers() |
| for handler in old_handlers: |
| logger.addHandler(handler) |
| |
| if 'tag_added' in context: |
| for handler in _current_handlers(): |
| tagging_formatter = handler.formatter |
| handler.setFormatter(tagging_formatter.base_formatter) |
| |
| |
| def _pop_context(self): |
| self._flush_all_streams() |
| context = self._context_stack.pop() |
| self._restore_context(context) |
| |
| |
| def undo_redirect(self): |
| """ |
| Undo the last redirection (that hasn't yet been undone). |
| |
| If any subprocesses have been launched since the redirection was |
| performed, they must have ended by the time this is called. Otherwise, |
| this will hang waiting for the logging subprocess to end. |
| """ |
| if not self._context_stack: |
| raise RuntimeError('No redirects to undo') |
| self._pop_context() |
| |
| |
| def restore(self): |
| """ |
| Same as undo_redirect(). For backwards compatibility with |
| fd_stack. |
| """ |
| self.undo_redirect() |
| |
| |
| class _FdRedirectionStreamManager(_StreamManager): |
| """ |
| Like StreamManager, but also captures output from subprocesses by modifying |
| the underlying file descriptors. |
| |
| For the underlying file descriptors, we spawn a subprocess that writes all |
| input to the logging module, and we point the FD to that subprocess. As a |
| result, every time we redirect output we need to spawn a new subprocess to |
| pick up the new logging settings (without disturbing any existing processes |
| using the old logging subprocess). |
| |
| If, one day, we could get all code using utils.run() and friends to launch |
| subprocesses, we'd no longer need to handle raw FD output, and we could |
| get rid of all this business with subprocesses. Another option would be |
| to capture all stray output to a single, separate destination. |
| """ |
| |
| WAITPID_TIMEOUT_S = 5 |
| WAITPID_SAMPLE_TIME_S = 0.1 |
| |
| def __init__(self, stream, level, stream_setter): |
| if not hasattr(stream, 'fileno'): |
| # with fake, in-process file objects, subprocess output won't be |
| # captured. this should never happen in normal use, since the |
| # factory methods will only pass sys.stdout and sys.stderr. |
| raise ValueError("FdRedirectionLoggingManager won't work with " |
| "streams that aren't backed by file " |
| "descriptors") |
| |
| super(_FdRedirectionStreamManager, self).__init__(stream, level, |
| stream_setter) |
| self._fd = stream.fileno() |
| self._fd_copy_stream = None |
| |
| |
| def _point_stream_handlers_to_copy(self): |
| """ |
| point logging StreamHandlers that point to this stream to a safe |
| copy of the underlying FD. otherwise, StreamHandler output will go |
| to the logging subprocess, effectively getting doubly logged. |
| """ |
| fd_copy = os.dup(self._fd) |
| self._fd_copy_stream = os.fdopen(fd_copy, 'w') |
| self._redirect_logging_stream_handlers(self._stream, |
| self._fd_copy_stream) |
| |
| |
| def _restore_stream_handlers(self): |
| """ point logging StreamHandlers back to the original FD """ |
| self._redirect_logging_stream_handlers(self._fd_copy_stream, |
| self._stream) |
| self._fd_copy_stream.close() |
| |
| |
| def _redirect_logging_stream_handlers(self, old_stream, new_stream): |
| """ |
| Redirect all configured logging StreamHandlers pointing to |
| old_stream to point to new_stream instead. |
| """ |
| for handler in _current_handlers(): |
| points_to_stream = (isinstance(handler, logging.StreamHandler) and |
| hasattr(handler.stream, 'fileno') and |
| handler.stream.fileno() == old_stream.fileno()) |
| if points_to_stream: |
| logger.removeHandler(handler) |
| handler.close() # doesn't close the stream, just the handler |
| |
| new_handler = logging.StreamHandler(new_stream) |
| new_handler.setLevel(handler.level) |
| new_handler.setFormatter(handler.formatter) |
| for log_filter in handler.filters: |
| new_handler.addFilter(log_filter) |
| logger.addHandler(new_handler) |
| |
| |
| def start_logging(self): |
| super(_FdRedirectionStreamManager, self).start_logging() |
| self._point_stream_handlers_to_copy() |
| |
| |
| def stop_logging(self): |
| super(_FdRedirectionStreamManager, self).stop_logging() |
| self._restore_stream_handlers() |
| |
| |
| def _spawn_logging_subprocess(self): |
| """ |
| Spawn a subprocess to log all input to the logging module with the |
| current settings, and direct output to it. |
| """ |
| read_end, write_end = os.pipe() |
| pid = os.fork() |
| if pid: # parent |
| os.close(read_end) |
| os.dup2(write_end, self._fd) # point FD to the subprocess |
| os.close(write_end) |
| fd_flags = fcntl.fcntl(self._fd, fcntl.F_GETFD) |
| fcntl.fcntl(self._fd, fcntl.F_SETFD, |
| fd_flags | fcntl.FD_CLOEXEC) |
| return pid |
| else: # child |
| try: |
| os.close(write_end) |
| # ensure this subprocess doesn't hold any pipes to others |
| os.close(1) |
| os.close(2) |
| self._run_logging_subprocess(read_end) # never returns |
| except: |
| # don't let exceptions in the child escape |
| try: |
| logging.exception('Logging subprocess died:') |
| finally: |
| os._exit(1) |
| |
| |
| def _run_logging_subprocess(self, read_fd): |
| """ |
| Always run from a subprocess. Read from read_fd and write to the |
| logging module until EOF. |
| """ |
| # A SIGTERM will be issued by the main process if it believes this |
| # subprocess to the stuck. In that case, simply exit with status 1. |
| # See below for pending TODO on how to remove this. |
| signal.signal(signal.SIGTERM, lambda signum, stack: os._exit(1)) |
| input_file = os.fdopen(read_fd, 'r') |
| for line in iter(input_file.readline, ''): |
| logging.log(self._level, line.rstrip('\n')) |
| logging.debug('Logging subprocess finished') |
| os._exit(0) |
| |
| |
| def _context_id(self): |
| return '%s_context' % id(self) |
| |
| |
| def on_push_context(self, context): |
| # adds a context dict for this stream, $id_context, with the following: |
| # * old_fd: FD holding a copy of the managed FD before launching a new |
| # subprocess. |
| # * child_pid: PID of the logging subprocess launched |
| fd_copy = os.dup(self._fd) |
| child_pid = self._spawn_logging_subprocess() |
| my_context = {'old_fd': fd_copy, 'child_pid': child_pid} |
| context[self._context_id()] = my_context |
| |
| |
| def on_restore_context(self, context): |
| my_context = context[self._context_id()] |
| |
| # shut down subprocess |
| child_pid = my_context['child_pid'] |
| try: |
| os.close(self._fd) |
| # TODO(crbug.com/970115): remove this work-around in favor of |
| # a clean waitpid(child_pid, 0) once the issue described in the |
| # bug is root caused and resolved. |
| end = time.time() + self.WAITPID_TIMEOUT_S |
| while time.time() < end: |
| if os.waitpid(child_pid, os.WNOHANG) != (0, 0): |
| break |
| time.sleep(self.WAITPID_SAMPLE_TIME_S) |
| else: |
| # After timeout the process still hasn't finished. Send a |
| # SIGTERM as it's likely stuck. |
| os.kill(child_pid, signal.SIGTERM) |
| logging.exception('Ended up killing logging subprocess at %s.', |
| child_pid) |
| except OSError: |
| logging.exception('Failed to cleanly shutdown logging subprocess:') |
| |
| # restore previous FD |
| old_fd = my_context['old_fd'] |
| os.dup2(old_fd, self._fd) |
| os.close(old_fd) |
| |
| |
| class FdRedirectionLoggingManager(LoggingManager): |
| """ |
| A simple extension of LoggingManager to use FdRedirectionStreamManagers, |
| so that managed streams have their underlying FDs redirected. |
| """ |
| |
| STREAM_MANAGER_CLASS = _FdRedirectionStreamManager |
| |
| def start_logging(self): |
| super(FdRedirectionLoggingManager, self).start_logging() |
| # spawn the initial logging subprocess |
| self._push_context(self._get_context()) |
| |
| |
| def undo_redirect(self): |
| # len == 1 would mean only start_logging() had been called (but no |
| # redirects had occurred) |
| if len(self._context_stack) < 2: |
| raise RuntimeError('No redirects to undo') |
| super(FdRedirectionLoggingManager, self).undo_redirect() |