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"""Unit tests for absl.logging."""
16
17import contextlib
18import functools
19import getpass
20import io
21import logging as std_logging
22import os
23import re
24import socket
25import sys
26import tempfile
27import threading
28import time
29import traceback
30import unittest
31from unittest import mock
32
33from absl import flags
34from absl import logging
35from absl.testing import absltest
36from absl.testing import flagsaver
37from absl.testing import parameterized
38
39FLAGS = flags.FLAGS
40
41
42class ConfigurationTest(absltest.TestCase):
43  """Tests the initial logging configuration."""
44
45  def test_logger_and_handler(self):
46    absl_logger = std_logging.getLogger('absl')
47    self.assertIs(absl_logger, logging.get_absl_logger())
48    self.assertIsInstance(absl_logger, logging.ABSLLogger)
49    self.assertIsInstance(
50        logging.get_absl_handler().python_handler.formatter,
51        logging.PythonFormatter)
52
53
54class LoggerLevelsTest(parameterized.TestCase):
55
56  def setUp(self):
57    super(LoggerLevelsTest, self).setUp()
58    # Since these tests muck with the flag, always save/restore in case the
59    # tests forget to clean up properly.
60    # enter_context() is py3-only, but manually enter/exit should suffice.
61    cm = self.set_logger_levels({})
62    cm.__enter__()
63    self.addCleanup(lambda: cm.__exit__(None, None, None))
64
65  @contextlib.contextmanager
66  def set_logger_levels(self, levels):
67    original_levels = {
68        name: std_logging.getLogger(name).level for name in levels
69    }
70
71    try:
72      with flagsaver.flagsaver(logger_levels=levels):
73        yield
74    finally:
75      for name, level in original_levels.items():
76        std_logging.getLogger(name).setLevel(level)
77
78  def assert_logger_level(self, name, expected_level):
79    logger = std_logging.getLogger(name)
80    self.assertEqual(logger.level, expected_level)
81
82  def assert_logged(self, logger_name, expected_msgs):
83    logger = std_logging.getLogger(logger_name)
84    # NOTE: assertLogs() sets the logger to INFO if not specified.
85    with self.assertLogs(logger, logger.level) as cm:
86      logger.debug('debug')
87      logger.info('info')
88      logger.warning('warning')
89      logger.error('error')
90      logger.critical('critical')
91
92    actual = {r.getMessage() for r in cm.records}
93    self.assertEqual(set(expected_msgs), actual)
94
95  def test_setting_levels(self):
96    # Other tests change the root logging level, so we can't
97    # assume it's the default.
98    orig_root_level = std_logging.root.getEffectiveLevel()
99    with self.set_logger_levels({'foo': 'ERROR', 'bar': 'DEBUG'}):
100
101      self.assert_logger_level('foo', std_logging.ERROR)
102      self.assert_logger_level('bar', std_logging.DEBUG)
103      self.assert_logger_level('', orig_root_level)
104
105      self.assert_logged('foo', {'error', 'critical'})
106      self.assert_logged('bar',
107                         {'debug', 'info', 'warning', 'error', 'critical'})
108
109  @parameterized.named_parameters(
110      ('empty', ''),
111      ('one_value', 'one:INFO'),
112      ('two_values', 'one.a:INFO,two.b:ERROR'),
113      ('whitespace_ignored', ' one : DEBUG , two : INFO'),
114  )
115  def test_serialize_parse(self, levels_str):
116    fl = FLAGS['logger_levels']
117    fl.parse(levels_str)
118    expected = levels_str.replace(' ', '')
119    actual = fl.serialize()
120    self.assertEqual('--logger_levels={}'.format(expected), actual)
121
122  def test_invalid_value(self):
123    with self.assertRaisesRegex(ValueError, 'Unknown level.*10'):
124      FLAGS['logger_levels'].parse('foo:10')
125
126
127class PythonHandlerTest(absltest.TestCase):
128  """Tests the PythonHandler class."""
129
130  def setUp(self):
131    super().setUp()
132    (year, month, day, hour, minute, sec,
133     dunno, dayofyear, dst_flag) = (1979, 10, 21, 18, 17, 16, 3, 15, 0)
134    self.now_tuple = (year, month, day, hour, minute, sec,
135                      dunno, dayofyear, dst_flag)
136    self.python_handler = logging.PythonHandler()
137
138  def tearDown(self):
139    mock.patch.stopall()
140    super().tearDown()
141
142  @flagsaver.flagsaver(logtostderr=False)
143  def test_set_google_log_file_no_log_to_stderr(self):
144    with mock.patch.object(self.python_handler, 'start_logging_to_file'):
145      self.python_handler.use_absl_log_file()
146      self.python_handler.start_logging_to_file.assert_called_once_with(
147          program_name=None, log_dir=None)
148
149  @flagsaver.flagsaver(logtostderr=True)
150  def test_set_google_log_file_with_log_to_stderr(self):
151    self.python_handler.stream = None
152    self.python_handler.use_absl_log_file()
153    self.assertEqual(sys.stderr, self.python_handler.stream)
154
155  @mock.patch.object(logging, 'find_log_dir_and_names')
156  @mock.patch.object(logging.time, 'localtime')
157  @mock.patch.object(logging.time, 'time')
158  @mock.patch.object(os.path, 'islink')
159  @mock.patch.object(os, 'unlink')
160  @mock.patch.object(os, 'getpid')
161  def test_start_logging_to_file(
162      self, mock_getpid, mock_unlink, mock_islink, mock_time,
163      mock_localtime, mock_find_log_dir_and_names):
164    mock_find_log_dir_and_names.return_value = ('here', 'prog1', 'prog1')
165    mock_time.return_value = '12345'
166    mock_localtime.return_value = self.now_tuple
167    mock_getpid.return_value = 4321
168    symlink = os.path.join('here', 'prog1.INFO')
169    mock_islink.return_value = True
170    with mock.patch.object(
171        logging, 'open', return_value=sys.stdout, create=True):
172      if getattr(os, 'symlink', None):
173        with mock.patch.object(os, 'symlink'):
174          self.python_handler.start_logging_to_file()
175          mock_unlink.assert_called_once_with(symlink)
176          os.symlink.assert_called_once_with(
177              'prog1.INFO.19791021-181716.4321', symlink)
178      else:
179        self.python_handler.start_logging_to_file()
180
181  def test_log_file(self):
182    handler = logging.PythonHandler()
183    self.assertEqual(sys.stderr, handler.stream)
184
185    stream = mock.Mock()
186    handler = logging.PythonHandler(stream)
187    self.assertEqual(stream, handler.stream)
188
189  def test_flush(self):
190    stream = mock.Mock()
191    handler = logging.PythonHandler(stream)
192    handler.flush()
193    stream.flush.assert_called_once()
194
195  def test_flush_with_value_error(self):
196    stream = mock.Mock()
197    stream.flush.side_effect = ValueError
198    handler = logging.PythonHandler(stream)
199    handler.flush()
200    stream.flush.assert_called_once()
201
202  def test_flush_with_environment_error(self):
203    stream = mock.Mock()
204    stream.flush.side_effect = EnvironmentError
205    handler = logging.PythonHandler(stream)
206    handler.flush()
207    stream.flush.assert_called_once()
208
209  def test_flush_with_assertion_error(self):
210    stream = mock.Mock()
211    stream.flush.side_effect = AssertionError
212    handler = logging.PythonHandler(stream)
213    with self.assertRaises(AssertionError):
214      handler.flush()
215
216  def test_ignore_flush_if_stream_is_none(self):
217    # Happens if creating a Windows executable without console.
218    with mock.patch.object(sys, 'stderr', new=None):
219      handler = logging.PythonHandler(None)
220      # Test that this does not fail.
221      handler.flush()
222
223  def test_ignore_flush_if_stream_does_not_support_flushing(self):
224    class BadStream:
225      pass
226
227    handler = logging.PythonHandler(BadStream())
228    # Test that this does not fail.
229    handler.flush()
230
231  def test_log_to_std_err(self):
232    record = std_logging.LogRecord(
233        'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
234    with mock.patch.object(std_logging.StreamHandler, 'emit'):
235      self.python_handler._log_to_stderr(record)
236      std_logging.StreamHandler.emit.assert_called_once_with(record)
237
238  @flagsaver.flagsaver(logtostderr=True)
239  def test_emit_log_to_stderr(self):
240    record = std_logging.LogRecord(
241        'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
242    with mock.patch.object(self.python_handler, '_log_to_stderr'):
243      self.python_handler.emit(record)
244      self.python_handler._log_to_stderr.assert_called_once_with(record)
245
246  def test_emit(self):
247    stream = io.StringIO()
248    handler = logging.PythonHandler(stream)
249    handler.stderr_threshold = std_logging.FATAL
250    record = std_logging.LogRecord(
251        'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
252    handler.emit(record)
253    self.assertEqual(1, stream.getvalue().count('logging_msg'))
254
255  @flagsaver.flagsaver(stderrthreshold='debug')
256  def test_emit_and_stderr_threshold(self):
257    mock_stderr = io.StringIO()
258    stream = io.StringIO()
259    handler = logging.PythonHandler(stream)
260    record = std_logging.LogRecord(
261        'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
262    with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr:
263      handler.emit(record)
264      self.assertEqual(1, stream.getvalue().count('logging_msg'))
265      self.assertEqual(1, mock_stderr.getvalue().count('logging_msg'))
266
267  @flagsaver.flagsaver(alsologtostderr=True)
268  def test_emit_also_log_to_stderr(self):
269    mock_stderr = io.StringIO()
270    stream = io.StringIO()
271    handler = logging.PythonHandler(stream)
272    handler.stderr_threshold = std_logging.FATAL
273    record = std_logging.LogRecord(
274        'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
275    with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr:
276      handler.emit(record)
277      self.assertEqual(1, stream.getvalue().count('logging_msg'))
278      self.assertEqual(1, mock_stderr.getvalue().count('logging_msg'))
279
280  def test_emit_on_stderr(self):
281    mock_stderr = io.StringIO()
282    with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr:
283      handler = logging.PythonHandler()
284      handler.stderr_threshold = std_logging.INFO
285      record = std_logging.LogRecord(
286          'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False)
287      handler.emit(record)
288      self.assertEqual(1, mock_stderr.getvalue().count('logging_msg'))
289
290  def test_emit_fatal_absl(self):
291    stream = io.StringIO()
292    handler = logging.PythonHandler(stream)
293    record = std_logging.LogRecord(
294        'name', std_logging.FATAL, 'path', 12, 'logging_msg', [], False)
295    record.__dict__[logging._ABSL_LOG_FATAL] = True
296    with mock.patch.object(handler, 'flush') as mock_flush:
297      with mock.patch.object(os, 'abort') as mock_abort:
298        handler.emit(record)
299        mock_abort.assert_called_once()
300        mock_flush.assert_called()  # flush is also called by super class.
301
302  def test_emit_fatal_non_absl(self):
303    stream = io.StringIO()
304    handler = logging.PythonHandler(stream)
305    record = std_logging.LogRecord(
306        'name', std_logging.FATAL, 'path', 12, 'logging_msg', [], False)
307    with mock.patch.object(os, 'abort') as mock_abort:
308      handler.emit(record)
309      mock_abort.assert_not_called()
310
311  def test_close(self):
312    stream = mock.Mock()
313    stream.isatty.return_value = True
314    handler = logging.PythonHandler(stream)
315    with mock.patch.object(handler, 'flush') as mock_flush:
316      with mock.patch.object(std_logging.StreamHandler, 'close') as super_close:
317        handler.close()
318        mock_flush.assert_called_once()
319        super_close.assert_called_once()
320        stream.close.assert_not_called()
321
322  def test_close_afile(self):
323    stream = mock.Mock()
324    stream.isatty.return_value = False
325    stream.close.side_effect = ValueError
326    handler = logging.PythonHandler(stream)
327    with mock.patch.object(handler, 'flush') as mock_flush:
328      with mock.patch.object(std_logging.StreamHandler, 'close') as super_close:
329        handler.close()
330        mock_flush.assert_called_once()
331        super_close.assert_called_once()
332
333  def test_close_stderr(self):
334    with mock.patch.object(sys, 'stderr') as mock_stderr:
335      mock_stderr.isatty.return_value = False
336      handler = logging.PythonHandler(sys.stderr)
337      handler.close()
338      mock_stderr.close.assert_not_called()
339
340  def test_close_stdout(self):
341    with mock.patch.object(sys, 'stdout') as mock_stdout:
342      mock_stdout.isatty.return_value = False
343      handler = logging.PythonHandler(sys.stdout)
344      handler.close()
345      mock_stdout.close.assert_not_called()
346
347  def test_close_original_stderr(self):
348    with mock.patch.object(sys, '__stderr__') as mock_original_stderr:
349      mock_original_stderr.isatty.return_value = False
350      handler = logging.PythonHandler(sys.__stderr__)
351      handler.close()
352      mock_original_stderr.close.assert_not_called()
353
354  def test_close_original_stdout(self):
355    with mock.patch.object(sys, '__stdout__') as mock_original_stdout:
356      mock_original_stdout.isatty.return_value = False
357      handler = logging.PythonHandler(sys.__stdout__)
358      handler.close()
359      mock_original_stdout.close.assert_not_called()
360
361  def test_close_fake_file(self):
362
363    class FakeFile(object):
364      """A file-like object that does not implement "isatty"."""
365
366      def __init__(self):
367        self.closed = False
368
369      def close(self):
370        self.closed = True
371
372      def flush(self):
373        pass
374
375    fake_file = FakeFile()
376    handler = logging.PythonHandler(fake_file)
377    handler.close()
378    self.assertTrue(fake_file.closed)
379
380
381class ABSLHandlerTest(absltest.TestCase):
382
383  def setUp(self):
384    super().setUp()
385    formatter = logging.PythonFormatter()
386    self.absl_handler = logging.ABSLHandler(formatter)
387
388  def test_activate_python_handler(self):
389    self.absl_handler.activate_python_handler()
390    self.assertEqual(
391        self.absl_handler._current_handler, self.absl_handler.python_handler)
392
393
394class ABSLLoggerTest(absltest.TestCase):
395  """Tests the ABSLLogger class."""
396
397  def set_up_mock_frames(self):
398    """Sets up mock frames for use with the testFindCaller methods."""
399    logging_file = os.path.join('absl', 'logging', '__init__.py')
400
401    # Set up mock frame 0
402    mock_frame_0 = mock.Mock()
403    mock_code_0 = mock.Mock()
404    mock_code_0.co_filename = logging_file
405    mock_code_0.co_name = 'LoggingLog'
406    mock_code_0.co_firstlineno = 124
407    mock_frame_0.f_code = mock_code_0
408    mock_frame_0.f_lineno = 125
409
410    # Set up mock frame 1
411    mock_frame_1 = mock.Mock()
412    mock_code_1 = mock.Mock()
413    mock_code_1.co_filename = 'myfile.py'
414    mock_code_1.co_name = 'Method1'
415    mock_code_1.co_firstlineno = 124
416    mock_frame_1.f_code = mock_code_1
417    mock_frame_1.f_lineno = 125
418
419    # Set up mock frame 2
420    mock_frame_2 = mock.Mock()
421    mock_code_2 = mock.Mock()
422    mock_code_2.co_filename = 'myfile.py'
423    mock_code_2.co_name = 'Method2'
424    mock_code_2.co_firstlineno = 124
425    mock_frame_2.f_code = mock_code_2
426    mock_frame_2.f_lineno = 125
427
428    # Set up mock frame 3
429    mock_frame_3 = mock.Mock()
430    mock_code_3 = mock.Mock()
431    mock_code_3.co_filename = 'myfile.py'
432    mock_code_3.co_name = 'Method3'
433    mock_code_3.co_firstlineno = 124
434    mock_frame_3.f_code = mock_code_3
435    mock_frame_3.f_lineno = 125
436
437    # Set up mock frame 4 that has the same function name as frame 2.
438    mock_frame_4 = mock.Mock()
439    mock_code_4 = mock.Mock()
440    mock_code_4.co_filename = 'myfile.py'
441    mock_code_4.co_name = 'Method2'
442    mock_code_4.co_firstlineno = 248
443    mock_frame_4.f_code = mock_code_4
444    mock_frame_4.f_lineno = 249
445
446    # Tie them together.
447    mock_frame_4.f_back = None
448    mock_frame_3.f_back = mock_frame_4
449    mock_frame_2.f_back = mock_frame_3
450    mock_frame_1.f_back = mock_frame_2
451    mock_frame_0.f_back = mock_frame_1
452
453    mock.patch.object(sys, '_getframe').start()
454    sys._getframe.return_value = mock_frame_0
455
456  def setUp(self):
457    super().setUp()
458    self.message = 'Hello Nurse'
459    self.logger = logging.ABSLLogger('')
460
461  def tearDown(self):
462    mock.patch.stopall()
463    self.logger._frames_to_skip.clear()
464    super().tearDown()
465
466  def test_constructor_without_level(self):
467    self.logger = logging.ABSLLogger('')
468    self.assertEqual(std_logging.NOTSET, self.logger.getEffectiveLevel())
469
470  def test_constructor_with_level(self):
471    self.logger = logging.ABSLLogger('', std_logging.DEBUG)
472    self.assertEqual(std_logging.DEBUG, self.logger.getEffectiveLevel())
473
474  def test_find_caller_normal(self):
475    self.set_up_mock_frames()
476    expected_name = 'Method1'
477    self.assertEqual(expected_name, self.logger.findCaller()[2])
478
479  def test_find_caller_skip_method1(self):
480    self.set_up_mock_frames()
481    self.logger.register_frame_to_skip('myfile.py', 'Method1')
482    expected_name = 'Method2'
483    self.assertEqual(expected_name, self.logger.findCaller()[2])
484
485  def test_find_caller_skip_method1_and_method2(self):
486    self.set_up_mock_frames()
487    self.logger.register_frame_to_skip('myfile.py', 'Method1')
488    self.logger.register_frame_to_skip('myfile.py', 'Method2')
489    expected_name = 'Method3'
490    self.assertEqual(expected_name, self.logger.findCaller()[2])
491
492  def test_find_caller_skip_method1_and_method3(self):
493    self.set_up_mock_frames()
494    self.logger.register_frame_to_skip('myfile.py', 'Method1')
495    # Skipping Method3 should change nothing since Method2 should be hit.
496    self.logger.register_frame_to_skip('myfile.py', 'Method3')
497    expected_name = 'Method2'
498    self.assertEqual(expected_name, self.logger.findCaller()[2])
499
500  def test_find_caller_skip_method1_and_method4(self):
501    self.set_up_mock_frames()
502    self.logger.register_frame_to_skip('myfile.py', 'Method1')
503    # Skipping frame 4's Method2 should change nothing for frame 2's Method2.
504    self.logger.register_frame_to_skip('myfile.py', 'Method2', 248)
505    expected_name = 'Method2'
506    expected_frame_lineno = 125
507    self.assertEqual(expected_name, self.logger.findCaller()[2])
508    self.assertEqual(expected_frame_lineno, self.logger.findCaller()[1])
509
510  def test_find_caller_skip_method1_method2_and_method3(self):
511    self.set_up_mock_frames()
512    self.logger.register_frame_to_skip('myfile.py', 'Method1')
513    self.logger.register_frame_to_skip('myfile.py', 'Method2', 124)
514    self.logger.register_frame_to_skip('myfile.py', 'Method3')
515    expected_name = 'Method2'
516    expected_frame_lineno = 249
517    self.assertEqual(expected_name, self.logger.findCaller()[2])
518    self.assertEqual(expected_frame_lineno, self.logger.findCaller()[1])
519
520  def test_find_caller_stack_info(self):
521    self.set_up_mock_frames()
522    self.logger.register_frame_to_skip('myfile.py', 'Method1')
523    with mock.patch.object(traceback, 'print_stack') as print_stack:
524      self.assertEqual(
525          ('myfile.py', 125, 'Method2', 'Stack (most recent call last):'),
526          self.logger.findCaller(stack_info=True))
527    print_stack.assert_called_once()
528
529  def test_critical(self):
530    with mock.patch.object(self.logger, 'log'):
531      self.logger.critical(self.message)
532      self.logger.log.assert_called_once_with(
533          std_logging.CRITICAL, self.message)
534
535  def test_fatal(self):
536    with mock.patch.object(self.logger, 'log'):
537      self.logger.fatal(self.message)
538      self.logger.log.assert_called_once_with(std_logging.FATAL, self.message)
539
540  def test_error(self):
541    with mock.patch.object(self.logger, 'log'):
542      self.logger.error(self.message)
543      self.logger.log.assert_called_once_with(std_logging.ERROR, self.message)
544
545  def test_warn(self):
546    with mock.patch.object(self.logger, 'log'):
547      self.logger.warn(self.message)
548      self.logger.log.assert_called_once_with(std_logging.WARN, self.message)
549
550  def test_warning(self):
551    with mock.patch.object(self.logger, 'log'):
552      self.logger.warning(self.message)
553      self.logger.log.assert_called_once_with(std_logging.WARNING, self.message)
554
555  def test_info(self):
556    with mock.patch.object(self.logger, 'log'):
557      self.logger.info(self.message)
558      self.logger.log.assert_called_once_with(std_logging.INFO, self.message)
559
560  def test_debug(self):
561    with mock.patch.object(self.logger, 'log'):
562      self.logger.debug(self.message)
563      self.logger.log.assert_called_once_with(std_logging.DEBUG, self.message)
564
565  def test_log_debug_with_python(self):
566    with mock.patch.object(self.logger, 'log'):
567      FLAGS.verbosity = 1
568      self.logger.debug(self.message)
569      self.logger.log.assert_called_once_with(std_logging.DEBUG, self.message)
570
571  def test_log_fatal_with_python(self):
572    with mock.patch.object(self.logger, 'log'):
573      self.logger.fatal(self.message)
574      self.logger.log.assert_called_once_with(std_logging.FATAL, self.message)
575
576  def test_register_frame_to_skip(self):
577    # This is basically just making sure that if I put something in a
578    # list, it actually appears in that list.
579    frame_tuple = ('file', 'method')
580    self.logger.register_frame_to_skip(*frame_tuple)
581    self.assertIn(frame_tuple, self.logger._frames_to_skip)
582
583  def test_register_frame_to_skip_with_lineno(self):
584    frame_tuple = ('file', 'method', 123)
585    self.logger.register_frame_to_skip(*frame_tuple)
586    self.assertIn(frame_tuple, self.logger._frames_to_skip)
587
588  def test_logger_cannot_be_disabled(self):
589    self.logger.disabled = True
590    record = self.logger.makeRecord(
591        'name', std_logging.INFO, 'fn', 20, 'msg', [], False)
592    with mock.patch.object(self.logger, 'callHandlers') as mock_call_handlers:
593      self.logger.handle(record)
594    mock_call_handlers.assert_called_once()
595
596
597class ABSLLogPrefixTest(parameterized.TestCase):
598
599  def setUp(self):
600    super().setUp()
601    self.record = std_logging.LogRecord(
602        'name', std_logging.INFO, 'path/to/source.py', 13, 'log message',
603        None, None)
604
605  @parameterized.named_parameters(
606      ('debug', std_logging.DEBUG, 'I'),
607      ('info', std_logging.INFO, 'I'),
608      ('warning', std_logging.WARNING, 'W'),
609      ('error', std_logging.ERROR, 'E'),
610  )
611  def test_default_prefixes(self, levelno, level_prefix):
612    self.record.levelno = levelno
613    self.record.created = 1494293880.378885
614    thread_id = '{: >5}'.format(logging._get_thread_id())
615    # Use UTC so the test passes regardless of the local time zone.
616    with mock.patch.object(time, 'localtime', side_effect=time.gmtime):
617      self.assertEqual(
618          '{}0509 01:38:00.378885 {} source.py:13] '.format(
619              level_prefix, thread_id),
620          logging.get_absl_log_prefix(self.record))
621      time.localtime.assert_called_once_with(self.record.created)
622
623  def test_absl_prefix_regex(self):
624    self.record.created = 1226888258.0521369
625    # Use UTC so the test passes regardless of the local time zone.
626    with mock.patch.object(time, 'localtime', side_effect=time.gmtime):
627      prefix = logging.get_absl_log_prefix(self.record)
628
629    match = re.search(logging.ABSL_LOGGING_PREFIX_REGEX, prefix)
630    self.assertTrue(match)
631
632    expect = {'severity': 'I',
633              'month': '11',
634              'day': '17',
635              'hour': '02',
636              'minute': '17',
637              'second': '38',
638              'microsecond': '052136',
639              'thread_id': str(logging._get_thread_id()),
640              'filename': 'source.py',
641              'line': '13',
642             }
643    actual = {name: match.group(name) for name in expect}
644    self.assertEqual(expect, actual)
645
646  def test_critical_absl(self):
647    self.record.levelno = std_logging.CRITICAL
648    self.record.created = 1494293880.378885
649    self.record._absl_log_fatal = True
650    thread_id = '{: >5}'.format(logging._get_thread_id())
651    # Use UTC so the test passes regardless of the local time zone.
652    with mock.patch.object(time, 'localtime', side_effect=time.gmtime):
653      self.assertEqual(
654          'F0509 01:38:00.378885 {} source.py:13] '.format(thread_id),
655          logging.get_absl_log_prefix(self.record))
656      time.localtime.assert_called_once_with(self.record.created)
657
658  def test_critical_non_absl(self):
659    self.record.levelno = std_logging.CRITICAL
660    self.record.created = 1494293880.378885
661    thread_id = '{: >5}'.format(logging._get_thread_id())
662    # Use UTC so the test passes regardless of the local time zone.
663    with mock.patch.object(time, 'localtime', side_effect=time.gmtime):
664      self.assertEqual(
665          'E0509 01:38:00.378885 {} source.py:13] CRITICAL - '.format(
666              thread_id),
667          logging.get_absl_log_prefix(self.record))
668      time.localtime.assert_called_once_with(self.record.created)
669
670
671class LogCountTest(absltest.TestCase):
672
673  def test_counter_threadsafe(self):
674    threads_start = threading.Event()
675    counts = set()
676    k = object()
677
678    def t():
679      threads_start.wait()
680      counts.add(logging._get_next_log_count_per_token(k))
681
682    threads = [threading.Thread(target=t) for _ in range(100)]
683    for thread in threads:
684      thread.start()
685    threads_start.set()
686    for thread in threads:
687      thread.join()
688    self.assertEqual(counts, {i for i in range(100)})
689
690
691class LoggingTest(absltest.TestCase):
692
693  def test_fatal(self):
694    with mock.patch.object(os, 'abort') as mock_abort:
695      logging.fatal('Die!')
696      mock_abort.assert_called_once()
697
698  def test_find_log_dir_with_arg(self):
699    with mock.patch.object(os, 'access'), \
700        mock.patch.object(os.path, 'isdir'):
701      os.path.isdir.return_value = True
702      os.access.return_value = True
703      log_dir = logging.find_log_dir(log_dir='./')
704      self.assertEqual('./', log_dir)
705
706  @flagsaver.flagsaver(log_dir='./')
707  def test_find_log_dir_with_flag(self):
708    with mock.patch.object(os, 'access'), \
709        mock.patch.object(os.path, 'isdir'):
710      os.path.isdir.return_value = True
711      os.access.return_value = True
712      log_dir = logging.find_log_dir()
713      self.assertEqual('./', log_dir)
714
715  @flagsaver.flagsaver(log_dir='')
716  def test_find_log_dir_with_hda_tmp(self):
717    with mock.patch.object(os, 'access'), \
718        mock.patch.object(os.path, 'exists'), \
719        mock.patch.object(os.path, 'isdir'):
720      os.path.exists.return_value = True
721      os.path.isdir.return_value = True
722      os.access.return_value = True
723      log_dir = logging.find_log_dir()
724      self.assertEqual(tempfile.gettempdir(), log_dir)
725
726  @flagsaver.flagsaver(log_dir='')
727  def test_find_log_dir_with_tmp(self):
728    with mock.patch.object(os, 'access'), \
729        mock.patch.object(os.path, 'exists'), \
730        mock.patch.object(os.path, 'isdir'):
731      os.path.exists.return_value = False
732      os.path.isdir.side_effect = lambda path: path == tempfile.gettempdir()
733      os.access.return_value = True
734      log_dir = logging.find_log_dir()
735      self.assertEqual(tempfile.gettempdir(), log_dir)
736
737  def test_find_log_dir_with_nothing(self):
738    with mock.patch.object(os.path, 'exists'), \
739        mock.patch.object(os.path, 'isdir'):
740      os.path.exists.return_value = False
741      os.path.isdir.return_value = False
742      with self.assertRaises(FileNotFoundError):
743        logging.find_log_dir()
744
745  def test_find_log_dir_and_names_with_args(self):
746    user = 'test_user'
747    host = 'test_host'
748    log_dir = 'here'
749    program_name = 'prog1'
750    with mock.patch.object(getpass, 'getuser'), \
751        mock.patch.object(logging, 'find_log_dir') as mock_find_log_dir, \
752        mock.patch.object(socket, 'gethostname') as mock_gethostname:
753      getpass.getuser.return_value = user
754      mock_gethostname.return_value = host
755      mock_find_log_dir.return_value = log_dir
756
757      prefix = '%s.%s.%s.log' % (program_name, host, user)
758      self.assertEqual((log_dir, prefix, program_name),
759                       logging.find_log_dir_and_names(
760                           program_name=program_name, log_dir=log_dir))
761
762  def test_find_log_dir_and_names_without_args(self):
763    user = 'test_user'
764    host = 'test_host'
765    log_dir = 'here'
766    py_program_name = 'py_prog1'
767    sys.argv[0] = 'path/to/prog1'
768    with mock.patch.object(getpass, 'getuser'), \
769        mock.patch.object(logging, 'find_log_dir') as mock_find_log_dir, \
770        mock.patch.object(socket, 'gethostname'):
771      getpass.getuser.return_value = user
772      socket.gethostname.return_value = host
773      mock_find_log_dir.return_value = log_dir
774      prefix = '%s.%s.%s.log' % (py_program_name, host, user)
775      self.assertEqual((log_dir, prefix, py_program_name),
776                       logging.find_log_dir_and_names())
777
778  def test_find_log_dir_and_names_wo_username(self):
779    # Windows doesn't have os.getuid at all
780    if hasattr(os, 'getuid'):
781      mock_getuid = mock.patch.object(os, 'getuid')
782      uid = 100
783      logged_uid = '100'
784    else:
785      # The function doesn't exist, but our test code still tries to mock
786      # it, so just use a fake thing.
787      mock_getuid = _mock_windows_os_getuid()
788      uid = -1
789      logged_uid = 'unknown'
790
791    host = 'test_host'
792    log_dir = 'here'
793    program_name = 'prog1'
794    with mock.patch.object(getpass, 'getuser'), \
795        mock_getuid as getuid, \
796        mock.patch.object(logging, 'find_log_dir') as mock_find_log_dir, \
797        mock.patch.object(socket, 'gethostname') as mock_gethostname:
798      getpass.getuser.side_effect = KeyError()
799      getuid.return_value = uid
800      mock_gethostname.return_value = host
801      mock_find_log_dir.return_value = log_dir
802
803      prefix = '%s.%s.%s.log' % (program_name, host, logged_uid)
804      self.assertEqual((log_dir, prefix, program_name),
805                       logging.find_log_dir_and_names(
806                           program_name=program_name, log_dir=log_dir))
807
808  def test_errors_in_logging(self):
809    with mock.patch.object(sys, 'stderr', new=io.StringIO()) as stderr:
810      logging.info('not enough args: %s %s', 'foo')  # pylint: disable=logging-too-few-args
811      self.assertIn('Traceback (most recent call last):', stderr.getvalue())
812      self.assertIn('TypeError', stderr.getvalue())
813
814  def test_dict_arg(self):
815    # Tests that passing a dictionary as a single argument does not crash.
816    logging.info('%(test)s', {'test': 'Hello world!'})
817
818  def test_exception_dict_format(self):
819    # Just verify that this doesn't raise a TypeError.
820    logging.exception('%(test)s', {'test': 'Hello world!'})
821
822  def test_exception_with_exc_info(self):
823    # Just verify that this doesn't raise a KeyeError.
824    logging.exception('exc_info=True', exc_info=True)
825    logging.exception('exc_info=False', exc_info=False)
826
827  def test_logging_levels(self):
828    old_level = logging.get_verbosity()
829
830    logging.set_verbosity(logging.DEBUG)
831    self.assertEqual(logging.get_verbosity(), logging.DEBUG)
832    self.assertTrue(logging.level_debug())
833    self.assertTrue(logging.level_info())
834    self.assertTrue(logging.level_warning())
835    self.assertTrue(logging.level_error())
836
837    logging.set_verbosity(logging.INFO)
838    self.assertEqual(logging.get_verbosity(), logging.INFO)
839    self.assertFalse(logging.level_debug())
840    self.assertTrue(logging.level_info())
841    self.assertTrue(logging.level_warning())
842    self.assertTrue(logging.level_error())
843
844    logging.set_verbosity(logging.WARNING)
845    self.assertEqual(logging.get_verbosity(), logging.WARNING)
846    self.assertFalse(logging.level_debug())
847    self.assertFalse(logging.level_info())
848    self.assertTrue(logging.level_warning())
849    self.assertTrue(logging.level_error())
850
851    logging.set_verbosity(logging.ERROR)
852    self.assertEqual(logging.get_verbosity(), logging.ERROR)
853    self.assertFalse(logging.level_debug())
854    self.assertFalse(logging.level_info())
855    self.assertTrue(logging.level_error())
856
857    logging.set_verbosity(old_level)
858
859  def test_set_verbosity_strings(self):
860    old_level = logging.get_verbosity()
861
862    # Lowercase names.
863    logging.set_verbosity('debug')
864    self.assertEqual(logging.get_verbosity(), logging.DEBUG)
865    logging.set_verbosity('info')
866    self.assertEqual(logging.get_verbosity(), logging.INFO)
867    logging.set_verbosity('warning')
868    self.assertEqual(logging.get_verbosity(), logging.WARNING)
869    logging.set_verbosity('warn')
870    self.assertEqual(logging.get_verbosity(), logging.WARNING)
871    logging.set_verbosity('error')
872    self.assertEqual(logging.get_verbosity(), logging.ERROR)
873    logging.set_verbosity('fatal')
874
875    # Uppercase names.
876    self.assertEqual(logging.get_verbosity(), logging.FATAL)
877    logging.set_verbosity('DEBUG')
878    self.assertEqual(logging.get_verbosity(), logging.DEBUG)
879    logging.set_verbosity('INFO')
880    self.assertEqual(logging.get_verbosity(), logging.INFO)
881    logging.set_verbosity('WARNING')
882    self.assertEqual(logging.get_verbosity(), logging.WARNING)
883    logging.set_verbosity('WARN')
884    self.assertEqual(logging.get_verbosity(), logging.WARNING)
885    logging.set_verbosity('ERROR')
886    self.assertEqual(logging.get_verbosity(), logging.ERROR)
887    logging.set_verbosity('FATAL')
888    self.assertEqual(logging.get_verbosity(), logging.FATAL)
889
890    # Integers as strings.
891    logging.set_verbosity(str(logging.DEBUG))
892    self.assertEqual(logging.get_verbosity(), logging.DEBUG)
893    logging.set_verbosity(str(logging.INFO))
894    self.assertEqual(logging.get_verbosity(), logging.INFO)
895    logging.set_verbosity(str(logging.WARNING))
896    self.assertEqual(logging.get_verbosity(), logging.WARNING)
897    logging.set_verbosity(str(logging.ERROR))
898    self.assertEqual(logging.get_verbosity(), logging.ERROR)
899    logging.set_verbosity(str(logging.FATAL))
900    self.assertEqual(logging.get_verbosity(), logging.FATAL)
901
902    logging.set_verbosity(old_level)
903
904  def test_key_flags(self):
905    key_flags = FLAGS.get_key_flags_for_module(logging)
906    key_flag_names = [flag.name for flag in key_flags]
907    self.assertIn('stderrthreshold', key_flag_names)
908    self.assertIn('verbosity', key_flag_names)
909
910  def test_get_absl_logger(self):
911    self.assertIsInstance(
912        logging.get_absl_logger(), logging.ABSLLogger)
913
914  def test_get_absl_handler(self):
915    self.assertIsInstance(
916        logging.get_absl_handler(), logging.ABSLHandler)
917
918
919@mock.patch.object(logging.ABSLLogger, 'register_frame_to_skip')
920class LogSkipPrefixTest(absltest.TestCase):
921  """Tests for logging.skip_log_prefix."""
922
923  def _log_some_info(self):
924    """Logging helper function for LogSkipPrefixTest."""
925    logging.info('info')
926
927  def _log_nested_outer(self):
928    """Nested logging helper functions for LogSkipPrefixTest."""
929    def _log_nested_inner():
930      logging.info('info nested')
931    return _log_nested_inner
932
933  def test_skip_log_prefix_with_name(self, mock_skip_register):
934    retval = logging.skip_log_prefix('_log_some_info')
935    mock_skip_register.assert_called_once_with(__file__, '_log_some_info', None)
936    self.assertEqual(retval, '_log_some_info')
937
938  def test_skip_log_prefix_with_func(self, mock_skip_register):
939    retval = logging.skip_log_prefix(self._log_some_info)
940    mock_skip_register.assert_called_once_with(
941        __file__, '_log_some_info', mock.ANY)
942    self.assertEqual(retval, self._log_some_info)
943
944  def test_skip_log_prefix_with_functools_partial(self, mock_skip_register):
945    partial_input = functools.partial(self._log_some_info)
946    with self.assertRaises(ValueError):
947      _ = logging.skip_log_prefix(partial_input)
948    mock_skip_register.assert_not_called()
949
950  def test_skip_log_prefix_with_lambda(self, mock_skip_register):
951    lambda_input = lambda _: self._log_some_info()
952    retval = logging.skip_log_prefix(lambda_input)
953    mock_skip_register.assert_called_once_with(__file__, '<lambda>', mock.ANY)
954    self.assertEqual(retval, lambda_input)
955
956  def test_skip_log_prefix_with_bad_input(self, mock_skip_register):
957    dict_input = {1: 2, 2: 3}
958    with self.assertRaises(TypeError):
959      _ = logging.skip_log_prefix(dict_input)
960    mock_skip_register.assert_not_called()
961
962  def test_skip_log_prefix_with_nested_func(self, mock_skip_register):
963    nested_input = self._log_nested_outer()
964    retval = logging.skip_log_prefix(nested_input)
965    mock_skip_register.assert_called_once_with(
966        __file__, '_log_nested_inner', mock.ANY)
967    self.assertEqual(retval, nested_input)
968
969  def test_skip_log_prefix_decorator(self, mock_skip_register):
970
971    @logging.skip_log_prefix
972    def _log_decorated():
973      logging.info('decorated')
974
975    del _log_decorated
976    mock_skip_register.assert_called_once_with(
977        __file__, '_log_decorated', mock.ANY)
978
979
980@contextlib.contextmanager
981def override_python_handler_stream(stream):
982  handler = logging.get_absl_handler().python_handler
983  old_stream = handler.stream
984  handler.stream = stream
985  try:
986    yield
987  finally:
988    handler.stream = old_stream
989
990
991class GetLogFileNameTest(parameterized.TestCase):
992
993  @parameterized.named_parameters(
994      ('err', sys.stderr),
995      ('out', sys.stdout),
996  )
997  def test_get_log_file_name_py_std(self, stream):
998    with override_python_handler_stream(stream):
999      self.assertEqual('', logging.get_log_file_name())
1000
1001  def test_get_log_file_name_py_no_name(self):
1002
1003    class FakeFile(object):
1004      pass
1005
1006    with override_python_handler_stream(FakeFile()):
1007      self.assertEqual('', logging.get_log_file_name())
1008
1009  def test_get_log_file_name_py_file(self):
1010    _, filename = tempfile.mkstemp(dir=absltest.TEST_TMPDIR.value)
1011    with open(filename, 'a') as stream:
1012      with override_python_handler_stream(stream):
1013        self.assertEqual(filename, logging.get_log_file_name())
1014
1015
1016@contextlib.contextmanager
1017def _mock_windows_os_getuid():
1018  yield mock.MagicMock()
1019
1020
1021if __name__ == '__main__':
1022  absltest.main()
1023