• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1"""
2Autotest has some surprisingly complicated logging behaviour.
3
4Managers allow you to define logging contexts, which define a set of rules on
5how to handle stdout/stderr.  The niceness that you get by going through the
6logging_manager for this is that you can push/pop these contexts.  So if you
7wish to temporarily change how logging works, this gives you that mechanism.
8
9Most of this file is actually setting up for a confusing
10fork-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
33Each top-level box is a process.  When autoserv starts up, it'll fork off a
34logging subprocess, and set its stdout/stderr fd's to the subprocess's stdin.
35When we fork to create the processes that will run the test code, they inherit
36this.  As do any processes they themselves fork and exec (such as shelling out
37to some command).  This isn't the nicest, as it involves closing and dup'ing
38over stdout/stderr, but it does make sure that the whole process tree logs to
39python logging in a very consistent way.
40"""
41
42
43import fcntl, logging, os, signal, sys, warnings
44
45# primary public APIs
46
47def 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
60def 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
80logger = logging.getLogger()
81
82
83def _current_handlers():
84    return set(logger.handlers)
85
86
87_caller_code_to_skip_in_logging_stack = set()
88
89
90def 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.
101def _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
124if 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
131logging.Logger.findCaller = _logging_manager_aware_logger__find_caller
132
133
134class 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
207class _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
266class 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
507class _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
663class 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