• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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