1# Copyright 2017 The Abseil Authors.
2#
3# Licensed under the Apache License, Version 2.0 (the "License");
4# you may not use this file except in compliance with the License.
5# You may obtain a copy of the License at
6#
7#      http://www.apache.org/licenses/LICENSE-2.0
8#
9# Unless required by applicable law or agreed to in writing, software
10# distributed under the License is distributed on an "AS IS" BASIS,
11# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12# See the License for the specific language governing permissions and
13# limitations under the License.
14
15"""Abseil Python logging module implemented on top of standard logging.
16
17Simple usage::
18
19    from absl import logging
20
21    logging.info('Interesting Stuff')
22    logging.info('Interesting Stuff with Arguments: %d', 42)
23
24    logging.set_verbosity(logging.INFO)
25    logging.log(logging.DEBUG, 'This will *not* be printed')
26    logging.set_verbosity(logging.DEBUG)
27    logging.log(logging.DEBUG, 'This will be printed')
28
29    logging.warning('Worrying Stuff')
30    logging.error('Alarming Stuff')
31    logging.fatal('AAAAHHHHH!!!!')  # Process exits.
32
33Usage note: Do not pre-format the strings in your program code.
34Instead, let the logging module perform argument interpolation.
35This saves cycles because strings that don't need to be printed
36are never formatted.  Note that this module does not attempt to
37interpolate arguments when no arguments are given.  In other words::
38
39    logging.info('Interesting Stuff: %s')
40
41does not raise an exception because logging.info() has only one
42argument, the message string.
43
44"Lazy" evaluation for debugging
45-------------------------------
46
47If you do something like this::
48
49    logging.debug('Thing: %s', thing.ExpensiveOp())
50
51then the ExpensiveOp will be evaluated even if nothing
52is printed to the log. To avoid this, use the level_debug() function::
53
54  if logging.level_debug():
55    logging.debug('Thing: %s', thing.ExpensiveOp())
56
57Per file level logging is supported by logging.vlog() and
58logging.vlog_is_on(). For example::
59
60    if logging.vlog_is_on(2):
61      logging.vlog(2, very_expensive_debug_message())
62
63Notes on Unicode
64----------------
65
66The log output is encoded as UTF-8.  Don't pass data in other encodings in
67bytes() instances -- instead pass unicode string instances when you need to
68(for both the format string and arguments).
69
70Note on critical and fatal:
71Standard logging module defines fatal as an alias to critical, but it's not
72documented, and it does NOT actually terminate the program.
73This module only defines fatal but not critical, and it DOES terminate the
74program.
75
76The differences in behavior are historical and unfortunate.
77"""
78
79import collections
80from collections import abc
81import getpass
82import io
83import itertools
84import logging
85import os
86import socket
87import struct
88import sys
89import tempfile
90import threading
91import time
92import timeit
93import traceback
94import types
95import warnings
96
97from absl import flags
98from absl.logging import converter
99
100# pylint: disable=g-import-not-at-top
101try:
102  from typing import NoReturn
103except ImportError:
104  pass
105
106# pylint: enable=g-import-not-at-top
107
108FLAGS = flags.FLAGS
109
110
111# Logging levels.
112FATAL = converter.ABSL_FATAL
113ERROR = converter.ABSL_ERROR
114WARNING = converter.ABSL_WARNING
115WARN = converter.ABSL_WARNING  # Deprecated name.
116INFO = converter.ABSL_INFO
117DEBUG = converter.ABSL_DEBUG
118
119# Regex to match/parse log line prefixes.
120ABSL_LOGGING_PREFIX_REGEX = (
121    r'^(?P<severity>[IWEF])'
122    r'(?P<month>\d\d)(?P<day>\d\d) '
123    r'(?P<hour>\d\d):(?P<minute>\d\d):(?P<second>\d\d)'
124    r'\.(?P<microsecond>\d\d\d\d\d\d) +'
125    r'(?P<thread_id>-?\d+) '
126    r'(?P<filename>[a-zA-Z<][\w._<>-]+):(?P<line>\d+)')
127
128
129# Mask to convert integer thread ids to unsigned quantities for logging purposes
130_THREAD_ID_MASK = 2 ** (struct.calcsize('L') * 8) - 1
131
132# Extra property set on the LogRecord created by ABSLLogger when its level is
133# CRITICAL/FATAL.
134_ABSL_LOG_FATAL = '_absl_log_fatal'
135# Extra prefix added to the log message when a non-absl logger logs a
136# CRITICAL/FATAL message.
137_CRITICAL_PREFIX = 'CRITICAL - '
138
139# Used by findCaller to skip callers from */logging/__init__.py.
140_LOGGING_FILE_PREFIX = os.path.join('logging', '__init__.')
141
142# The ABSL logger instance, initialized in _initialize().
143_absl_logger = None
144# The ABSL handler instance, initialized in _initialize().
145_absl_handler = None
146
147
148_CPP_NAME_TO_LEVELS = {
149    'debug': '0',  # Abseil C++ has no DEBUG level, mapping it to INFO here.
150    'info': '0',
151    'warning': '1',
152    'warn': '1',
153    'error': '2',
154    'fatal': '3'
155}
156
157_CPP_LEVEL_TO_NAMES = {
158    '0': 'info',
159    '1': 'warning',
160    '2': 'error',
161    '3': 'fatal',
162}
163
164
165class _VerbosityFlag(flags.Flag):
166  """Flag class for -v/--verbosity."""
167
168  def __init__(self, *args, **kwargs):
169    super(_VerbosityFlag, self).__init__(
170        flags.IntegerParser(),
171        flags.ArgumentSerializer(),
172        *args, **kwargs)
173
174  @property
175  def value(self):
176    return self._value
177
178  @value.setter
179  def value(self, v):
180    self._value = v
181    self._update_logging_levels()
182
183  def _update_logging_levels(self):
184    """Updates absl logging levels to the current verbosity.
185
186    Visibility: module-private
187    """
188    if not _absl_logger:
189      return
190
191    if self._value <= converter.ABSL_DEBUG:
192      standard_verbosity = converter.absl_to_standard(self._value)
193    else:
194      # --verbosity is set to higher than 1 for vlog.
195      standard_verbosity = logging.DEBUG - (self._value - 1)
196
197    # Also update root level when absl_handler is used.
198    if _absl_handler in logging.root.handlers:
199      # Make absl logger inherit from the root logger. absl logger might have
200      # a non-NOTSET value if logging.set_verbosity() is called at import time.
201      _absl_logger.setLevel(logging.NOTSET)
202      logging.root.setLevel(standard_verbosity)
203    else:
204      _absl_logger.setLevel(standard_verbosity)
205
206
207class _LoggerLevelsFlag(flags.Flag):
208  """Flag class for --logger_levels."""
209
210  def __init__(self, *args, **kwargs):
211    super(_LoggerLevelsFlag, self).__init__(
212        _LoggerLevelsParser(),
213        _LoggerLevelsSerializer(),
214        *args, **kwargs)
215
216  @property
217  def value(self):
218    # For lack of an immutable type, be defensive and return a copy.
219    # Modifications to the dict aren't supported and won't have any affect.
220    # While Py3 could use MappingProxyType, that isn't deepcopy friendly, so
221    # just return a copy.
222    return self._value.copy()
223
224  @value.setter
225  def value(self, v):
226    self._value = {} if v is None else v
227    self._update_logger_levels()
228
229  def _update_logger_levels(self):
230    # Visibility: module-private.
231    # This is called by absl.app.run() during initialization.
232    for name, level in self._value.items():
233      logging.getLogger(name).setLevel(level)
234
235
236class _LoggerLevelsParser(flags.ArgumentParser):
237  """Parser for --logger_levels flag."""
238
239  def parse(self, value):
240    if isinstance(value, abc.Mapping):
241      return value
242
243    pairs = [pair.strip() for pair in value.split(',') if pair.strip()]
244
245    # Preserve the order so that serialization is deterministic.
246    levels = collections.OrderedDict()
247    for name_level in pairs:
248      name, level = name_level.split(':', 1)
249      name = name.strip()
250      level = level.strip()
251      levels[name] = level
252    return levels
253
254
255class _LoggerLevelsSerializer(object):
256  """Serializer for --logger_levels flag."""
257
258  def serialize(self, value):
259    if isinstance(value, str):
260      return value
261    return ','.join(
262        '{}:{}'.format(name, level) for name, level in value.items())
263
264
265class _StderrthresholdFlag(flags.Flag):
266  """Flag class for --stderrthreshold."""
267
268  def __init__(self, *args, **kwargs):
269    super(_StderrthresholdFlag, self).__init__(
270        flags.ArgumentParser(),
271        flags.ArgumentSerializer(),
272        *args, **kwargs)
273
274  @property
275  def value(self):
276    return self._value
277
278  @value.setter
279  def value(self, v):
280    if v in _CPP_LEVEL_TO_NAMES:
281      # --stderrthreshold also accepts numeric strings whose values are
282      # Abseil C++ log levels.
283      cpp_value = int(v)
284      v = _CPP_LEVEL_TO_NAMES[v]  # Normalize to strings.
285    elif v.lower() in _CPP_NAME_TO_LEVELS:
286      v = v.lower()
287      if v == 'warn':
288        v = 'warning'  # Use 'warning' as the canonical name.
289      cpp_value = int(_CPP_NAME_TO_LEVELS[v])
290    else:
291      raise ValueError(
292          '--stderrthreshold must be one of (case-insensitive) '
293          "'debug', 'info', 'warning', 'error', 'fatal', "
294          "or '0', '1', '2', '3', not '%s'" % v)
295
296    self._value = v
297
298
299LOGTOSTDERR = flags.DEFINE_boolean(
300    'logtostderr',
301    False,
302    'Should only log to stderr?',
303    allow_override_cpp=True,
304)
305ALSOLOGTOSTDERR = flags.DEFINE_boolean(
306    'alsologtostderr',
307    False,
308    'also log to stderr?',
309    allow_override_cpp=True,
310)
311LOG_DIR = flags.DEFINE_string(
312    'log_dir',
313    os.getenv('TEST_TMPDIR', ''),
314    'directory to write logfiles into',
315    allow_override_cpp=True,
316)
317VERBOSITY = flags.DEFINE_flag(
318    _VerbosityFlag(
319        'verbosity',
320        -1,
321        (
322            'Logging verbosity level. Messages logged at this level or lower'
323            ' will be included. Set to 1 for debug logging. If the flag was not'
324            ' set or supplied, the value will be changed from the default of -1'
325            ' (warning) to 0 (info) after flags are parsed.'
326        ),
327        short_name='v',
328        allow_hide_cpp=True,
329    )
330)
331LOGGER_LEVELS = flags.DEFINE_flag(
332    _LoggerLevelsFlag(
333        'logger_levels',
334        {},
335        (
336            'Specify log level of loggers. The format is a CSV list of '
337            '`name:level`. Where `name` is the logger name used with '
338            '`logging.getLogger()`, and `level` is a level name  (INFO, DEBUG, '
339            'etc). e.g. `myapp.foo:INFO,other.logger:DEBUG`'
340        ),
341    )
342)
343STDERRTHRESHOLD = flags.DEFINE_flag(
344    _StderrthresholdFlag(
345        'stderrthreshold',
346        'fatal',
347        (
348            'log messages at this level, or more severe, to stderr in '
349            'addition to the logfile.  Possible values are '
350            "'debug', 'info', 'warning', 'error', and 'fatal'.  "
351            'Obsoletes --alsologtostderr. Using --alsologtostderr '
352            'cancels the effect of this flag. Please also note that '
353            'this flag is subject to --verbosity and requires logfile '
354            'not be stderr.'
355        ),
356        allow_hide_cpp=True,
357    )
358)
359SHOWPREFIXFORINFO = flags.DEFINE_boolean(
360    'showprefixforinfo',
361    True,
362    (
363        'If False, do not prepend prefix to info messages '
364        "when it's logged to stderr, "
365        '--verbosity is set to INFO level, '
366        'and python logging is used.'
367    ),
368)
369
370
371def get_verbosity():
372  """Returns the logging verbosity."""
373  return FLAGS['verbosity'].value
374
375
376def set_verbosity(v):
377  """Sets the logging verbosity.
378
379  Causes all messages of level <= v to be logged,
380  and all messages of level > v to be silently discarded.
381
382  Args:
383    v: int|str, the verbosity level as an integer or string. Legal string values
384        are those that can be coerced to an integer as well as case-insensitive
385        'debug', 'info', 'warning', 'error', and 'fatal'.
386  """
387  try:
388    new_level = int(v)
389  except ValueError:
390    new_level = converter.ABSL_NAMES[v.upper()]
391  FLAGS.verbosity = new_level
392
393
394def set_stderrthreshold(s):
395  """Sets the stderr threshold to the value passed in.
396
397  Args:
398    s: str|int, valid strings values are case-insensitive 'debug',
399        'info', 'warning', 'error', and 'fatal'; valid integer values are
400        logging.DEBUG|INFO|WARNING|ERROR|FATAL.
401
402  Raises:
403      ValueError: Raised when s is an invalid value.
404  """
405  if s in converter.ABSL_LEVELS:
406    FLAGS.stderrthreshold = converter.ABSL_LEVELS[s]
407  elif isinstance(s, str) and s.upper() in converter.ABSL_NAMES:
408    FLAGS.stderrthreshold = s
409  else:
410    raise ValueError(
411        'set_stderrthreshold only accepts integer absl logging level '
412        'from -3 to 1, or case-insensitive string values '
413        "'debug', 'info', 'warning', 'error', and 'fatal'. "
414        'But found "{}" ({}).'.format(s, type(s)))
415
416
417def fatal(msg, *args, **kwargs):
418  # type: (Any, Any, Any) -> NoReturn
419  """Logs a fatal message."""
420  log(FATAL, msg, *args, **kwargs)
421
422
423def error(msg, *args, **kwargs):
424  """Logs an error message."""
425  log(ERROR, msg, *args, **kwargs)
426
427
428def warning(msg, *args, **kwargs):
429  """Logs a warning message."""
430  log(WARNING, msg, *args, **kwargs)
431
432
433def warn(msg, *args, **kwargs):
434  """Deprecated, use 'warning' instead."""
435  warnings.warn("The 'warn' function is deprecated, use 'warning' instead",
436                DeprecationWarning, 2)
437  log(WARNING, msg, *args, **kwargs)
438
439
440def info(msg, *args, **kwargs):
441  """Logs an info message."""
442  log(INFO, msg, *args, **kwargs)
443
444
445def debug(msg, *args, **kwargs):
446  """Logs a debug message."""
447  log(DEBUG, msg, *args, **kwargs)
448
449
450def exception(msg, *args, exc_info=True, **kwargs):
451  """Logs an exception, with traceback and message."""
452  error(msg, *args, exc_info=exc_info, **kwargs)
453
454
455# Counter to keep track of number of log entries per token.
456_log_counter_per_token = {}
457
458
459def _get_next_log_count_per_token(token):
460  """Wrapper for _log_counter_per_token. Thread-safe.
461
462  Args:
463    token: The token for which to look up the count.
464
465  Returns:
466    The number of times this function has been called with
467    *token* as an argument (starting at 0).
468  """
469  # Can't use a defaultdict because defaultdict isn't atomic, whereas
470  # setdefault is.
471  return next(_log_counter_per_token.setdefault(token, itertools.count()))
472
473
474def log_every_n(level, msg, n, *args):
475  """Logs ``msg % args`` at level 'level' once per 'n' times.
476
477  Logs the 1st call, (N+1)st call, (2N+1)st call,  etc.
478  Not threadsafe.
479
480  Args:
481    level: int, the absl logging level at which to log.
482    msg: str, the message to be logged.
483    n: int, the number of times this should be called before it is logged.
484    *args: The args to be substituted into the msg.
485  """
486  count = _get_next_log_count_per_token(get_absl_logger().findCaller())
487  log_if(level, msg, not (count % n), *args)
488
489
490# Keeps track of the last log time of the given token.
491# Note: must be a dict since set/get is atomic in CPython.
492# Note: entries are never released as their number is expected to be low.
493_log_timer_per_token = {}
494
495
496def _seconds_have_elapsed(token, num_seconds):
497  """Tests if 'num_seconds' have passed since 'token' was requested.
498
499  Not strictly thread-safe - may log with the wrong frequency if called
500  concurrently from multiple threads. Accuracy depends on resolution of
501  'timeit.default_timer()'.
502
503  Always returns True on the first call for a given 'token'.
504
505  Args:
506    token: The token for which to look up the count.
507    num_seconds: The number of seconds to test for.
508
509  Returns:
510    Whether it has been >= 'num_seconds' since 'token' was last requested.
511  """
512  now = timeit.default_timer()
513  then = _log_timer_per_token.get(token, None)
514  if then is None or (now - then) >= num_seconds:
515    _log_timer_per_token[token] = now
516    return True
517  else:
518    return False
519
520
521def log_every_n_seconds(level, msg, n_seconds, *args):
522  """Logs ``msg % args`` at level ``level`` iff ``n_seconds`` elapsed since last call.
523
524  Logs the first call, logs subsequent calls if 'n' seconds have elapsed since
525  the last logging call from the same call site (file + line). Not thread-safe.
526
527  Args:
528    level: int, the absl logging level at which to log.
529    msg: str, the message to be logged.
530    n_seconds: float or int, seconds which should elapse before logging again.
531    *args: The args to be substituted into the msg.
532  """
533  should_log = _seconds_have_elapsed(get_absl_logger().findCaller(), n_seconds)
534  log_if(level, msg, should_log, *args)
535
536
537def log_first_n(level, msg, n, *args):
538  """Logs ``msg % args`` at level ``level`` only first ``n`` times.
539
540  Not threadsafe.
541
542  Args:
543    level: int, the absl logging level at which to log.
544    msg: str, the message to be logged.
545    n: int, the maximal number of times the message is logged.
546    *args: The args to be substituted into the msg.
547  """
548  count = _get_next_log_count_per_token(get_absl_logger().findCaller())
549  log_if(level, msg, count < n, *args)
550
551
552def log_if(level, msg, condition, *args):
553  """Logs ``msg % args`` at level ``level`` only if condition is fulfilled."""
554  if condition:
555    log(level, msg, *args)
556
557
558def log(level, msg, *args, **kwargs):
559  """Logs ``msg % args`` at absl logging level ``level``.
560
561  If no args are given just print msg, ignoring any interpolation specifiers.
562
563  Args:
564    level: int, the absl logging level at which to log the message
565        (logging.DEBUG|INFO|WARNING|ERROR|FATAL). While some C++ verbose logging
566        level constants are also supported, callers should prefer explicit
567        logging.vlog() calls for such purpose.
568
569    msg: str, the message to be logged.
570    *args: The args to be substituted into the msg.
571    **kwargs: May contain exc_info to add exception traceback to message.
572  """
573  if level > converter.ABSL_DEBUG:
574    # Even though this function supports level that is greater than 1, users
575    # should use logging.vlog instead for such cases.
576    # Treat this as vlog, 1 is equivalent to DEBUG.
577    standard_level = converter.STANDARD_DEBUG - (level - 1)
578  else:
579    if level < converter.ABSL_FATAL:
580      level = converter.ABSL_FATAL
581    standard_level = converter.absl_to_standard(level)
582
583  # Match standard logging's behavior. Before use_absl_handler() and
584  # logging is configured, there is no handler attached on _absl_logger nor
585  # logging.root. So logs go no where.
586  if not logging.root.handlers:
587    logging.basicConfig()
588
589  _absl_logger.log(standard_level, msg, *args, **kwargs)
590
591
592def vlog(level, msg, *args, **kwargs):
593  """Log ``msg % args`` at C++ vlog level ``level``.
594
595  Args:
596    level: int, the C++ verbose logging level at which to log the message,
597        e.g. 1, 2, 3, 4... While absl level constants are also supported,
598        callers should prefer logging.log|debug|info|... calls for such purpose.
599    msg: str, the message to be logged.
600    *args: The args to be substituted into the msg.
601    **kwargs: May contain exc_info to add exception traceback to message.
602  """
603  log(level, msg, *args, **kwargs)
604
605
606def vlog_is_on(level):
607  """Checks if vlog is enabled for the given level in caller's source file.
608
609  Args:
610    level: int, the C++ verbose logging level at which to log the message,
611        e.g. 1, 2, 3, 4... While absl level constants are also supported,
612        callers should prefer level_debug|level_info|... calls for
613        checking those.
614
615  Returns:
616    True if logging is turned on for that level.
617  """
618
619  if level > converter.ABSL_DEBUG:
620    # Even though this function supports level that is greater than 1, users
621    # should use logging.vlog instead for such cases.
622    # Treat this as vlog, 1 is equivalent to DEBUG.
623    standard_level = converter.STANDARD_DEBUG - (level - 1)
624  else:
625    if level < converter.ABSL_FATAL:
626      level = converter.ABSL_FATAL
627    standard_level = converter.absl_to_standard(level)
628  return _absl_logger.isEnabledFor(standard_level)
629
630
631def flush():
632  """Flushes all log files."""
633  get_absl_handler().flush()
634
635
636def level_debug():
637  """Returns True if debug logging is turned on."""
638  return get_verbosity() >= DEBUG
639
640
641def level_info():
642  """Returns True if info logging is turned on."""
643  return get_verbosity() >= INFO
644
645
646def level_warning():
647  """Returns True if warning logging is turned on."""
648  return get_verbosity() >= WARNING
649
650
651level_warn = level_warning  # Deprecated function.
652
653
654def level_error():
655  """Returns True if error logging is turned on."""
656  return get_verbosity() >= ERROR
657
658
659def get_log_file_name(level=INFO):
660  """Returns the name of the log file.
661
662  For Python logging, only one file is used and level is ignored. And it returns
663  empty string if it logs to stderr/stdout or the log stream has no `name`
664  attribute.
665
666  Args:
667    level: int, the absl.logging level.
668
669  Raises:
670    ValueError: Raised when `level` has an invalid value.
671  """
672  if level not in converter.ABSL_LEVELS:
673    raise ValueError('Invalid absl.logging level {}'.format(level))
674  stream = get_absl_handler().python_handler.stream
675  if (stream == sys.stderr or stream == sys.stdout or
676      not hasattr(stream, 'name')):
677    return ''
678  else:
679    return stream.name
680
681
682def find_log_dir_and_names(program_name=None, log_dir=None):
683  """Computes the directory and filename prefix for log file.
684
685  Args:
686    program_name: str|None, the filename part of the path to the program that
687        is running without its extension.  e.g: if your program is called
688        ``usr/bin/foobar.py`` this method should probably be called with
689        ``program_name='foobar`` However, this is just a convention, you can
690        pass in any string you want, and it will be used as part of the
691        log filename. If you don't pass in anything, the default behavior
692        is as described in the example.  In python standard logging mode,
693        the program_name will be prepended with ``py_`` if it is the
694        ``program_name`` argument is omitted.
695    log_dir: str|None, the desired log directory.
696
697  Returns:
698    (log_dir, file_prefix, symlink_prefix)
699
700  Raises:
701    FileNotFoundError: raised in Python 3 when it cannot find a log directory.
702    OSError: raised in Python 2 when it cannot find a log directory.
703  """
704  if not program_name:
705    # Strip the extension (foobar.par becomes foobar, and
706    # fubar.py becomes fubar). We do this so that the log
707    # file names are similar to C++ log file names.
708    program_name = os.path.splitext(os.path.basename(sys.argv[0]))[0]
709
710    # Prepend py_ to files so that python code gets a unique file, and
711    # so that C++ libraries do not try to write to the same log files as us.
712    program_name = 'py_%s' % program_name
713
714  actual_log_dir = find_log_dir(log_dir=log_dir)
715
716  try:
717    username = getpass.getuser()
718  except KeyError:
719    # This can happen, e.g. when running under docker w/o passwd file.
720    if hasattr(os, 'getuid'):
721      # Windows doesn't have os.getuid
722      username = str(os.getuid())
723    else:
724      username = 'unknown'
725  hostname = socket.gethostname()
726  file_prefix = '%s.%s.%s.log' % (program_name, hostname, username)
727
728  return actual_log_dir, file_prefix, program_name
729
730
731def find_log_dir(log_dir=None):
732  """Returns the most suitable directory to put log files into.
733
734  Args:
735    log_dir: str|None, if specified, the logfile(s) will be created in that
736        directory.  Otherwise if the --log_dir command-line flag is provided,
737        the logfile will be created in that directory.  Otherwise the logfile
738        will be created in a standard location.
739
740  Raises:
741    FileNotFoundError: raised in Python 3 when it cannot find a log directory.
742    OSError: raised in Python 2 when it cannot find a log directory.
743  """
744  # Get a list of possible log dirs (will try to use them in order).
745  # NOTE: Google's internal implementation has a special handling for Google
746  # machines, which uses a list of directories. Hence the following uses `dirs`
747  # instead of a single directory.
748  if log_dir:
749    # log_dir was explicitly specified as an arg, so use it and it alone.
750    dirs = [log_dir]
751  elif FLAGS['log_dir'].value:
752    # log_dir flag was provided, so use it and it alone (this mimics the
753    # behavior of the same flag in logging.cc).
754    dirs = [FLAGS['log_dir'].value]
755  else:
756    dirs = [tempfile.gettempdir()]
757
758  # Find the first usable log dir.
759  for d in dirs:
760    if os.path.isdir(d) and os.access(d, os.W_OK):
761      return d
762  raise FileNotFoundError(
763      "Can't find a writable directory for logs, tried %s" % dirs)
764
765
766def get_absl_log_prefix(record):
767  """Returns the absl log prefix for the log record.
768
769  Args:
770    record: logging.LogRecord, the record to get prefix for.
771  """
772  created_tuple = time.localtime(record.created)
773  created_microsecond = int(record.created % 1.0 * 1e6)
774
775  critical_prefix = ''
776  level = record.levelno
777  if _is_non_absl_fatal_record(record):
778    # When the level is FATAL, but not logged from absl, lower the level so
779    # it's treated as ERROR.
780    level = logging.ERROR
781    critical_prefix = _CRITICAL_PREFIX
782  severity = converter.get_initial_for_level(level)
783
784  return '%c%02d%02d %02d:%02d:%02d.%06d %5d %s:%d] %s' % (
785      severity,
786      created_tuple.tm_mon,
787      created_tuple.tm_mday,
788      created_tuple.tm_hour,
789      created_tuple.tm_min,
790      created_tuple.tm_sec,
791      created_microsecond,
792      _get_thread_id(),
793      record.filename,
794      record.lineno,
795      critical_prefix)
796
797
798def skip_log_prefix(func):
799  """Skips reporting the prefix of a given function or name by :class:`~absl.logging.ABSLLogger`.
800
801  This is a convenience wrapper function / decorator for
802  :meth:`~absl.logging.ABSLLogger.register_frame_to_skip`.
803
804  If a callable function is provided, only that function will be skipped.
805  If a function name is provided, all functions with the same name in the
806  file that this is called in will be skipped.
807
808  This can be used as a decorator of the intended function to be skipped.
809
810  Args:
811    func: Callable function or its name as a string.
812
813  Returns:
814    func (the input, unchanged).
815
816  Raises:
817    ValueError: The input is callable but does not have a function code object.
818    TypeError: The input is neither callable nor a string.
819  """
820  if callable(func):
821    func_code = getattr(func, '__code__', None)
822    if func_code is None:
823      raise ValueError('Input callable does not have a function code object.')
824    file_name = func_code.co_filename
825    func_name = func_code.co_name
826    func_lineno = func_code.co_firstlineno
827  elif isinstance(func, str):
828    file_name = get_absl_logger().findCaller()[0]
829    func_name = func
830    func_lineno = None
831  else:
832    raise TypeError('Input is neither callable nor a string.')
833  ABSLLogger.register_frame_to_skip(file_name, func_name, func_lineno)
834  return func
835
836
837def _is_non_absl_fatal_record(log_record):
838  return (log_record.levelno >= logging.FATAL and
839          not log_record.__dict__.get(_ABSL_LOG_FATAL, False))
840
841
842def _is_absl_fatal_record(log_record):
843  return (log_record.levelno >= logging.FATAL and
844          log_record.__dict__.get(_ABSL_LOG_FATAL, False))
845
846
847# Indicates if we still need to warn about pre-init logs going to stderr.
848_warn_preinit_stderr = True
849
850
851class PythonHandler(logging.StreamHandler):
852  """The handler class used by Abseil Python logging implementation."""
853
854  def __init__(self, stream=None, formatter=None):
855    super(PythonHandler, self).__init__(stream)
856    self.setFormatter(formatter or PythonFormatter())
857
858  def start_logging_to_file(self, program_name=None, log_dir=None):
859    """Starts logging messages to files instead of standard error."""
860    FLAGS.logtostderr = False
861
862    actual_log_dir, file_prefix, symlink_prefix = find_log_dir_and_names(
863        program_name=program_name, log_dir=log_dir)
864
865    basename = '%s.INFO.%s.%d' % (
866        file_prefix,
867        time.strftime('%Y%m%d-%H%M%S', time.localtime(time.time())),
868        os.getpid())
869    filename = os.path.join(actual_log_dir, basename)
870
871    self.stream = open(filename, 'a', encoding='utf-8')
872
873    # os.symlink is not available on Windows Python 2.
874    if getattr(os, 'symlink', None):
875      # Create a symlink to the log file with a canonical name.
876      symlink = os.path.join(actual_log_dir, symlink_prefix + '.INFO')
877      try:
878        if os.path.islink(symlink):
879          os.unlink(symlink)
880        os.symlink(os.path.basename(filename), symlink)
881      except EnvironmentError:
882        # If it fails, we're sad but it's no error.  Commonly, this
883        # fails because the symlink was created by another user and so
884        # we can't modify it
885        pass
886
887  def use_absl_log_file(self, program_name=None, log_dir=None):
888    """Conditionally logs to files, based on --logtostderr."""
889    if FLAGS['logtostderr'].value:
890      self.stream = sys.stderr
891    else:
892      self.start_logging_to_file(program_name=program_name, log_dir=log_dir)
893
894  def flush(self):
895    """Flushes all log files."""
896    self.acquire()
897    try:
898      if self.stream and hasattr(self.stream, 'flush'):
899        self.stream.flush()
900    except (EnvironmentError, ValueError):
901      # A ValueError is thrown if we try to flush a closed file.
902      pass
903    finally:
904      self.release()
905
906  def _log_to_stderr(self, record):
907    """Emits the record to stderr.
908
909    This temporarily sets the handler stream to stderr, calls
910    StreamHandler.emit, then reverts the stream back.
911
912    Args:
913      record: logging.LogRecord, the record to log.
914    """
915    # emit() is protected by a lock in logging.Handler, so we don't need to
916    # protect here again.
917    old_stream = self.stream
918    self.stream = sys.stderr
919    try:
920      super(PythonHandler, self).emit(record)
921    finally:
922      self.stream = old_stream
923
924  def emit(self, record):
925    """Prints a record out to some streams.
926
927    1. If ``FLAGS.logtostderr`` is set, it will print to ``sys.stderr`` ONLY.
928    2. If ``FLAGS.alsologtostderr`` is set, it will print to ``sys.stderr``.
929    3. If ``FLAGS.logtostderr`` is not set, it will log to the stream
930        associated with the current thread.
931
932    Args:
933      record: :class:`logging.LogRecord`, the record to emit.
934    """
935    # People occasionally call logging functions at import time before
936    # our flags may have even been defined yet, let alone even parsed, as we
937    # rely on the C++ side to define some flags for us and app init to
938    # deal with parsing.  Match the C++ library behavior of notify and emit
939    # such messages to stderr.  It encourages people to clean-up and does
940    # not hide the message.
941    level = record.levelno
942    if not FLAGS.is_parsed():  # Also implies "before flag has been defined".
943      global _warn_preinit_stderr
944      if _warn_preinit_stderr:
945        sys.stderr.write(
946            'WARNING: Logging before flag parsing goes to stderr.\n')
947        _warn_preinit_stderr = False
948      self._log_to_stderr(record)
949    elif FLAGS['logtostderr'].value:
950      self._log_to_stderr(record)
951    else:
952      super(PythonHandler, self).emit(record)
953      stderr_threshold = converter.string_to_standard(
954          FLAGS['stderrthreshold'].value)
955      if ((FLAGS['alsologtostderr'].value or level >= stderr_threshold) and
956          self.stream != sys.stderr):
957        self._log_to_stderr(record)
958    # Die when the record is created from ABSLLogger and level is FATAL.
959    if _is_absl_fatal_record(record):
960      self.flush()  # Flush the log before dying.
961
962      # In threaded python, sys.exit() from a non-main thread only
963      # exits the thread in question.
964      os.abort()
965
966  def close(self):
967    """Closes the stream to which we are writing."""
968    self.acquire()
969    try:
970      self.flush()
971      try:
972        # Do not close the stream if it's sys.stderr|stdout. They may be
973        # redirected or overridden to files, which should be managed by users
974        # explicitly.
975        user_managed = sys.stderr, sys.stdout, sys.__stderr__, sys.__stdout__
976        if self.stream not in user_managed and (
977            not hasattr(self.stream, 'isatty') or not self.stream.isatty()):
978          self.stream.close()
979      except ValueError:
980        # A ValueError is thrown if we try to run isatty() on a closed file.
981        pass
982      super(PythonHandler, self).close()
983    finally:
984      self.release()
985
986
987class ABSLHandler(logging.Handler):
988  """Abseil Python logging module's log handler."""
989
990  def __init__(self, python_logging_formatter):
991    super(ABSLHandler, self).__init__()
992
993    self._python_handler = PythonHandler(formatter=python_logging_formatter)
994    self.activate_python_handler()
995
996  def format(self, record):
997    return self._current_handler.format(record)
998
999  def setFormatter(self, fmt):
1000    self._current_handler.setFormatter(fmt)
1001
1002  def emit(self, record):
1003    self._current_handler.emit(record)
1004
1005  def flush(self):
1006    self._current_handler.flush()
1007
1008  def close(self):
1009    super(ABSLHandler, self).close()
1010    self._current_handler.close()
1011
1012  def handle(self, record):
1013    rv = self.filter(record)
1014    if rv:
1015      return self._current_handler.handle(record)
1016    return rv
1017
1018  @property
1019  def python_handler(self):
1020    return self._python_handler
1021
1022  def activate_python_handler(self):
1023    """Uses the Python logging handler as the current logging handler."""
1024    self._current_handler = self._python_handler
1025
1026  def use_absl_log_file(self, program_name=None, log_dir=None):
1027    self._current_handler.use_absl_log_file(program_name, log_dir)
1028
1029  def start_logging_to_file(self, program_name=None, log_dir=None):
1030    self._current_handler.start_logging_to_file(program_name, log_dir)
1031
1032
1033class PythonFormatter(logging.Formatter):
1034  """Formatter class used by :class:`~absl.logging.PythonHandler`."""
1035
1036  def format(self, record):
1037    """Appends the message from the record to the results of the prefix.
1038
1039    Args:
1040      record: logging.LogRecord, the record to be formatted.
1041
1042    Returns:
1043      The formatted string representing the record.
1044    """
1045    if (not FLAGS['showprefixforinfo'].value and
1046        FLAGS['verbosity'].value == converter.ABSL_INFO and
1047        record.levelno == logging.INFO and
1048        _absl_handler.python_handler.stream == sys.stderr):
1049      prefix = ''
1050    else:
1051      prefix = get_absl_log_prefix(record)
1052    return prefix + super(PythonFormatter, self).format(record)
1053
1054
1055class ABSLLogger(logging.getLoggerClass()):
1056  """A logger that will create LogRecords while skipping some stack frames.
1057
1058  This class maintains an internal list of filenames and method names
1059  for use when determining who called the currently executing stack
1060  frame.  Any method names from specific source files are skipped when
1061  walking backwards through the stack.
1062
1063  Client code should use the register_frame_to_skip method to let the
1064  ABSLLogger know which method from which file should be
1065  excluded from the walk backwards through the stack.
1066  """
1067  _frames_to_skip = set()
1068
1069  def findCaller(self, stack_info=False, stacklevel=1):
1070    """Finds the frame of the calling method on the stack.
1071
1072    This method skips any frames registered with the
1073    ABSLLogger and any methods from this file, and whatever
1074    method is currently being used to generate the prefix for the log
1075    line.  Then it returns the file name, line number, and method name
1076    of the calling method.  An optional fourth item may be returned,
1077    callers who only need things from the first three are advised to
1078    always slice or index the result rather than using direct unpacking
1079    assignment.
1080
1081    Args:
1082      stack_info: bool, when True, include the stack trace as a fourth item
1083          returned.  On Python 3 there are always four items returned - the
1084          fourth will be None when this is False.  On Python 2 the stdlib
1085          base class API only returns three items.  We do the same when this
1086          new parameter is unspecified or False for compatibility.
1087
1088    Returns:
1089      (filename, lineno, methodname[, sinfo]) of the calling method.
1090    """
1091    f_to_skip = ABSLLogger._frames_to_skip
1092    # Use sys._getframe(2) instead of logging.currentframe(), it's slightly
1093    # faster because there is one less frame to traverse.
1094    frame = sys._getframe(2)  # pylint: disable=protected-access
1095
1096    while frame:
1097      code = frame.f_code
1098      if (_LOGGING_FILE_PREFIX not in code.co_filename and
1099          (code.co_filename, code.co_name,
1100           code.co_firstlineno) not in f_to_skip and
1101          (code.co_filename, code.co_name) not in f_to_skip):
1102        sinfo = None
1103        if stack_info:
1104          out = io.StringIO()
1105          out.write(u'Stack (most recent call last):\n')
1106          traceback.print_stack(frame, file=out)
1107          sinfo = out.getvalue().rstrip(u'\n')
1108        return (code.co_filename, frame.f_lineno, code.co_name, sinfo)
1109      frame = frame.f_back
1110
1111  def critical(self, msg, *args, **kwargs):
1112    """Logs ``msg % args`` with severity ``CRITICAL``."""
1113    self.log(logging.CRITICAL, msg, *args, **kwargs)
1114
1115  def fatal(self, msg, *args, **kwargs):
1116    """Logs ``msg % args`` with severity ``FATAL``."""
1117    self.log(logging.FATAL, msg, *args, **kwargs)
1118
1119  def error(self, msg, *args, **kwargs):
1120    """Logs ``msg % args`` with severity ``ERROR``."""
1121    self.log(logging.ERROR, msg, *args, **kwargs)
1122
1123  def warn(self, msg, *args, **kwargs):
1124    """Logs ``msg % args`` with severity ``WARN``."""
1125    warnings.warn("The 'warn' method is deprecated, use 'warning' instead",
1126                  DeprecationWarning, 2)
1127    self.log(logging.WARN, msg, *args, **kwargs)
1128
1129  def warning(self, msg, *args, **kwargs):
1130    """Logs ``msg % args`` with severity ``WARNING``."""
1131    self.log(logging.WARNING, msg, *args, **kwargs)
1132
1133  def info(self, msg, *args, **kwargs):
1134    """Logs ``msg % args`` with severity ``INFO``."""
1135    self.log(logging.INFO, msg, *args, **kwargs)
1136
1137  def debug(self, msg, *args, **kwargs):
1138    """Logs ``msg % args`` with severity ``DEBUG``."""
1139    self.log(logging.DEBUG, msg, *args, **kwargs)
1140
1141  def log(self, level, msg, *args, **kwargs):
1142    """Logs a message at a cetain level substituting in the supplied arguments.
1143
1144    This method behaves differently in python and c++ modes.
1145
1146    Args:
1147      level: int, the standard logging level at which to log the message.
1148      msg: str, the text of the message to log.
1149      *args: The arguments to substitute in the message.
1150      **kwargs: The keyword arguments to substitute in the message.
1151    """
1152    if level >= logging.FATAL:
1153      # Add property to the LogRecord created by this logger.
1154      # This will be used by the ABSLHandler to determine whether it should
1155      # treat CRITICAL/FATAL logs as really FATAL.
1156      extra = kwargs.setdefault('extra', {})
1157      extra[_ABSL_LOG_FATAL] = True
1158    super(ABSLLogger, self).log(level, msg, *args, **kwargs)
1159
1160  def handle(self, record):
1161    """Calls handlers without checking ``Logger.disabled``.
1162
1163    Non-root loggers are set to disabled after setup with :func:`logging.config`
1164    if it's not explicitly specified. Historically, absl logging will not be
1165    disabled by that. To maintaining this behavior, this function skips
1166    checking the ``Logger.disabled`` bit.
1167
1168    This logger can still be disabled by adding a filter that filters out
1169    everything.
1170
1171    Args:
1172      record: logging.LogRecord, the record to handle.
1173    """
1174    if self.filter(record):
1175      self.callHandlers(record)
1176
1177  @classmethod
1178  def register_frame_to_skip(cls, file_name, function_name, line_number=None):
1179    """Registers a function name to skip when walking the stack.
1180
1181    The :class:`~absl.logging.ABSLLogger` sometimes skips method calls on the
1182    stack to make the log messages meaningful in their appropriate context.
1183    This method registers a function from a particular file as one
1184    which should be skipped.
1185
1186    Args:
1187      file_name: str, the name of the file that contains the function.
1188      function_name: str, the name of the function to skip.
1189      line_number: int, if provided, only the function with this starting line
1190          number will be skipped. Otherwise, all functions with the same name
1191          in the file will be skipped.
1192    """
1193    if line_number is not None:
1194      cls._frames_to_skip.add((file_name, function_name, line_number))
1195    else:
1196      cls._frames_to_skip.add((file_name, function_name))
1197
1198
1199def _get_thread_id():
1200  """Gets id of current thread, suitable for logging as an unsigned quantity.
1201
1202  If pywrapbase is linked, returns GetTID() for the thread ID to be
1203  consistent with C++ logging.  Otherwise, returns the numeric thread id.
1204  The quantities are made unsigned by masking with 2*sys.maxint + 1.
1205
1206  Returns:
1207    Thread ID unique to this process (unsigned)
1208  """
1209  thread_id = threading.get_ident()
1210  return thread_id & _THREAD_ID_MASK
1211
1212
1213def get_absl_logger():
1214  """Returns the absl logger instance."""
1215  assert _absl_logger is not None
1216  return _absl_logger
1217
1218
1219def get_absl_handler():
1220  """Returns the absl handler instance."""
1221  assert _absl_handler is not None
1222  return _absl_handler
1223
1224
1225def use_python_logging(quiet=False):
1226  """Uses the python implementation of the logging code.
1227
1228  Args:
1229    quiet: No logging message about switching logging type.
1230  """
1231  get_absl_handler().activate_python_handler()
1232  if not quiet:
1233    info('Restoring pure python logging')
1234
1235
1236_attempted_to_remove_stderr_stream_handlers = False
1237
1238
1239def use_absl_handler():
1240  """Uses the ABSL logging handler for logging.
1241
1242  This method is called in :func:`app.run()<absl.app.run>` so the absl handler
1243  is used in absl apps.
1244  """
1245  global _attempted_to_remove_stderr_stream_handlers
1246  if not _attempted_to_remove_stderr_stream_handlers:
1247    # The absl handler logs to stderr by default. To prevent double logging to
1248    # stderr, the following code tries its best to remove other handlers that
1249    # emit to stderr. Those handlers are most commonly added when
1250    # logging.info/debug is called before calling use_absl_handler().
1251    handlers = [
1252        h for h in logging.root.handlers
1253        if isinstance(h, logging.StreamHandler) and h.stream == sys.stderr]
1254    for h in handlers:
1255      logging.root.removeHandler(h)
1256    _attempted_to_remove_stderr_stream_handlers = True
1257
1258  absl_handler = get_absl_handler()
1259  if absl_handler not in logging.root.handlers:
1260    logging.root.addHandler(absl_handler)
1261    FLAGS['verbosity']._update_logging_levels()  # pylint: disable=protected-access
1262    FLAGS['logger_levels']._update_logger_levels()  # pylint: disable=protected-access
1263
1264
1265def _initialize():
1266  """Initializes loggers and handlers."""
1267  global _absl_logger, _absl_handler
1268
1269  if _absl_logger:
1270    return
1271
1272  original_logger_class = logging.getLoggerClass()
1273  logging.setLoggerClass(ABSLLogger)
1274  _absl_logger = logging.getLogger('absl')
1275  logging.setLoggerClass(original_logger_class)
1276
1277  python_logging_formatter = PythonFormatter()
1278  _absl_handler = ABSLHandler(python_logging_formatter)
1279
1280
1281_initialize()
1282