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"""Functional tests for absl.logging."""
16
17import fnmatch
18import os
19import re
20import shutil
21import subprocess
22import sys
23import tempfile
24
25from absl import logging
26from absl.testing import _bazelize_command
27from absl.testing import absltest
28from absl.testing import parameterized
29
30
31_PY_VLOG3_LOG_MESSAGE = """\
32I1231 23:59:59.000000 12345 logging_functional_test_helper.py:62] This line is VLOG level 3
33"""
34
35_PY_VLOG2_LOG_MESSAGE = """\
36I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] This line is VLOG level 2
37I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] This line is log level 2
38I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] VLOG level 1, but only if VLOG level 2 is active
39"""
40
41# VLOG1 is the same as DEBUG logs.
42_PY_DEBUG_LOG_MESSAGE = """\
43I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level 1
44I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level 1
45I1231 23:59:59.000000 12345 logging_functional_test_helper.py:66] This line is DEBUG
46"""
47
48_PY_INFO_LOG_MESSAGE = """\
49I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level 0
50I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level 0
51I1231 23:59:59.000000 12345 logging_functional_test_helper.py:70] Interesting Stuff\0
52I1231 23:59:59.000000 12345 logging_functional_test_helper.py:71] Interesting Stuff with Arguments: 42
53I1231 23:59:59.000000 12345 logging_functional_test_helper.py:73] Interesting Stuff with Dictionary
54I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times.
55I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times.
56I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times.
57I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times.
58I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times.
59I1231 23:59:59.000000 12345 logging_functional_test_helper.py:76] Info first 1 of 2
60I1231 23:59:59.000000 12345 logging_functional_test_helper.py:77] Info 1 (every 3)
61I1231 23:59:59.000000 12345 logging_functional_test_helper.py:76] Info first 2 of 2
62I1231 23:59:59.000000 12345 logging_functional_test_helper.py:77] Info 4 (every 3)
63"""
64
65_PY_INFO_LOG_MESSAGE_NOPREFIX = """\
66This line is VLOG level 0
67This line is log level 0
68Interesting Stuff\0
69Interesting Stuff with Arguments: 42
70Interesting Stuff with Dictionary
71This should appear 5 times.
72This should appear 5 times.
73This should appear 5 times.
74This should appear 5 times.
75This should appear 5 times.
76Info first 1 of 2
77Info 1 (every 3)
78Info first 2 of 2
79Info 4 (every 3)
80"""
81
82_PY_WARNING_LOG_MESSAGE = """\
83W1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level -1
84W1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level -1
85W1231 23:59:59.000000 12345 logging_functional_test_helper.py:79] Worrying Stuff
86W0000 23:59:59.000000 12345 logging_functional_test_helper.py:81] Warn first 1 of 2
87W0000 23:59:59.000000 12345 logging_functional_test_helper.py:82] Warn 1 (every 3)
88W0000 23:59:59.000000 12345 logging_functional_test_helper.py:81] Warn first 2 of 2
89W0000 23:59:59.000000 12345 logging_functional_test_helper.py:82] Warn 4 (every 3)
90"""
91
92if sys.version_info[0:2] == (3, 4):
93  _FAKE_ERROR_EXTRA_MESSAGE = """\
94Traceback (most recent call last):
95  File "logging_functional_test_helper.py", line 456, in _test_do_logging
96    raise OSError('Fake Error')
97"""
98else:
99  _FAKE_ERROR_EXTRA_MESSAGE = ''
100
101_PY_ERROR_LOG_MESSAGE = """\
102E1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level -2
103E1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level -2
104E1231 23:59:59.000000 12345 logging_functional_test_helper.py:87] An Exception %s
105Traceback (most recent call last):
106  File "logging_functional_test_helper.py", line 456, in _test_do_logging
107    raise OSError('Fake Error')
108OSError: Fake Error
109E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Once more, just because
110Traceback (most recent call last):
111  File "./logging_functional_test_helper.py", line 78, in _test_do_logging
112    raise OSError('Fake Error')
113OSError: Fake Error
114E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Exception 2 %s
115Traceback (most recent call last):
116  File "logging_functional_test_helper.py", line 456, in _test_do_logging
117    raise OSError('Fake Error')
118OSError: Fake Error
119E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Non-exception
120E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Exception 3
121Traceback (most recent call last):
122  File "logging_functional_test_helper.py", line 456, in _test_do_logging
123    raise OSError('Fake Error')
124OSError: Fake Error
125E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] No traceback
126{fake_error_extra}OSError: Fake Error
127E1231 23:59:59.000000 12345 logging_functional_test_helper.py:90] Alarming Stuff
128E0000 23:59:59.000000 12345 logging_functional_test_helper.py:92] Error first 1 of 2
129E0000 23:59:59.000000 12345 logging_functional_test_helper.py:93] Error 1 (every 3)
130E0000 23:59:59.000000 12345 logging_functional_test_helper.py:92] Error first 2 of 2
131E0000 23:59:59.000000 12345 logging_functional_test_helper.py:93] Error 4 (every 3)
132""".format(fake_error_extra=_FAKE_ERROR_EXTRA_MESSAGE)
133
134
135_CRITICAL_DOWNGRADE_TO_ERROR_MESSAGE = """\
136E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] CRITICAL - A critical message
137"""
138
139
140_VERBOSITY_FLAG_TEST_PARAMETERS = (
141    ('fatal', logging.FATAL),
142    ('error', logging.ERROR),
143    ('warning', logging.WARN),
144    ('info', logging.INFO),
145    ('debug', logging.DEBUG),
146    ('vlog1', 1),
147    ('vlog2', 2),
148    ('vlog3', 3))
149
150
151def _get_fatal_log_expectation(testcase, message, include_stacktrace):
152  """Returns the expectation for fatal logging tests.
153
154  Args:
155    testcase: The TestCase instance.
156    message: The extra fatal logging message.
157    include_stacktrace: Whether or not to include stacktrace.
158
159  Returns:
160    A callable, the expectation for fatal logging tests. It will be passed to
161    FunctionalTest._exec_test as third items in the expected_logs list.
162    See _exec_test's docstring for more information.
163  """
164  def assert_logs(logs):
165    if os.name == 'nt':
166      # On Windows, it also dumps extra information at the end, something like:
167      # This application has requested the Runtime to terminate it in an
168      # unusual way. Please contact the application's support team for more
169      # information.
170      logs = '\n'.join(logs.split('\n')[:-3])
171    format_string = (
172        'F1231 23:59:59.000000 12345 logging_functional_test_helper.py:175] '
173        '%s message\n')
174    expected_logs = format_string % message
175    if include_stacktrace:
176      expected_logs += 'Stack trace:\n'
177    faulthandler_start = 'Fatal Python error: Aborted'
178    testcase.assertIn(faulthandler_start, logs)
179    log_message = logs.split(faulthandler_start)[0]
180    testcase.assertEqual(_munge_log(expected_logs), _munge_log(log_message))
181
182  return assert_logs
183
184
185def _munge_log(buf):
186  """Remove timestamps, thread ids, filenames and line numbers from logs."""
187
188  # Remove all messages produced before the output to be tested.
189  buf = re.sub(r'(?:.|\n)*START OF TEST HELPER LOGS: IGNORE PREVIOUS.\n',
190               r'',
191               buf)
192
193  # Greeting
194  buf = re.sub(r'(?m)^Log file created at: .*\n',
195               '',
196               buf)
197  buf = re.sub(r'(?m)^Running on machine: .*\n',
198               '',
199               buf)
200  buf = re.sub(r'(?m)^Binary: .*\n',
201               '',
202               buf)
203  buf = re.sub(r'(?m)^Log line format: .*\n',
204               '',
205               buf)
206
207  # Verify thread id is logged as a non-negative quantity.
208  matched = re.match(r'(?m)^(\w)(\d\d\d\d \d\d:\d\d:\d\d\.\d\d\d\d\d\d) '
209                     r'([ ]*-?[0-9a-fA-f]+ )?([a-zA-Z<][\w._<>-]+):(\d+)',
210                     buf)
211  if matched:
212    threadid = matched.group(3)
213    if int(threadid) < 0:
214      raise AssertionError("Negative threadid '%s' in '%s'" % (threadid, buf))
215
216  # Timestamp
217  buf = re.sub(r'(?m)' + logging.ABSL_LOGGING_PREFIX_REGEX,
218               r'\g<severity>0000 00:00:00.000000 12345 \g<filename>:123',
219               buf)
220
221  # Traceback
222  buf = re.sub(r'(?m)^  File "(.*/)?([^"/]+)", line (\d+),',
223               r'  File "\g<2>", line 456,',
224               buf)
225
226  # Stack trace is too complicated for re, just assume it extends to end of
227  # output
228  buf = re.sub(r'(?sm)^Stack trace:\n.*',
229               r'Stack trace:\n',
230               buf)
231  buf = re.sub(r'(?sm)^\*\*\* Signal 6 received by PID.*\n.*',
232               r'Stack trace:\n',
233               buf)
234  buf = re.sub((r'(?sm)^\*\*\* ([A-Z]+) received by PID (\d+) '
235                r'\(TID 0x([0-9a-f]+)\)'
236                r'( from PID \d+)?; stack trace: \*\*\*\n.*'),
237               r'Stack trace:\n',
238               buf)
239  buf = re.sub(r'(?sm)^\*\*\* Check failure stack trace: \*\*\*\n.*',
240               r'Stack trace:\n',
241               buf)
242
243  if os.name == 'nt':
244    # On windows, we calls Python interpreter explicitly, so the file names
245    # include the full path. Strip them.
246    buf = re.sub(r'(  File ").*(logging_functional_test_helper\.py", line )',
247                 r'\1\2',
248                 buf)
249
250  return buf
251
252
253def _verify_status(expected, actual, output):
254  if expected != actual:
255    raise AssertionError(
256        'Test exited with unexpected status code %d (expected %d). '
257        'Output was:\n%s' % (actual, expected, output))
258
259
260def _verify_ok(status, output):
261  """Check that helper exited with no errors."""
262  _verify_status(0, status, output)
263
264
265def _verify_fatal(status, output):
266  """Check that helper died as expected."""
267  # os.abort generates a SIGABRT signal (-6). On Windows, the process
268  # immediately returns an exit code of 3.
269  # See https://docs.python.org/3.6/library/os.html#os.abort.
270  expected_exit_code = 3 if os.name == 'nt' else -6
271  _verify_status(expected_exit_code, status, output)
272
273
274def _verify_assert(status, output):
275  """.Check that helper failed with assertion."""
276  _verify_status(1, status, output)
277
278
279class FunctionalTest(parameterized.TestCase):
280  """Functional tests using the logging_functional_test_helper script."""
281
282  def _get_helper(self):
283    helper_name = 'absl/logging/tests/logging_functional_test_helper'
284    return _bazelize_command.get_executable_path(helper_name)
285
286  def _get_logs(self,
287                verbosity,
288                include_info_prefix=True):
289    logs = []
290    if verbosity >= 3:
291      logs.append(_PY_VLOG3_LOG_MESSAGE)
292    if verbosity >= 2:
293      logs.append(_PY_VLOG2_LOG_MESSAGE)
294    if verbosity >= logging.DEBUG:
295      logs.append(_PY_DEBUG_LOG_MESSAGE)
296
297    if verbosity >= logging.INFO:
298      if include_info_prefix:
299        logs.append(_PY_INFO_LOG_MESSAGE)
300      else:
301        logs.append(_PY_INFO_LOG_MESSAGE_NOPREFIX)
302    if verbosity >= logging.WARN:
303      logs.append(_PY_WARNING_LOG_MESSAGE)
304    if verbosity >= logging.ERROR:
305      logs.append(_PY_ERROR_LOG_MESSAGE)
306
307    expected_logs = ''.join(logs)
308    expected_logs = expected_logs.replace(
309        "<type 'exceptions.OSError'>", "<class 'OSError'>")
310    return expected_logs
311
312  def setUp(self):
313    super(FunctionalTest, self).setUp()
314    self._log_dir = tempfile.mkdtemp(dir=absltest.TEST_TMPDIR.value)
315
316  def tearDown(self):
317    shutil.rmtree(self._log_dir)
318    super(FunctionalTest, self).tearDown()
319
320  def _exec_test(self,
321                 verify_exit_fn,
322                 expected_logs,
323                 test_name='do_logging',
324                 pass_logtostderr=False,
325                 use_absl_log_file=False,
326                 show_info_prefix=1,
327                 call_dict_config=False,
328                 extra_args=()):
329    """Execute the helper script and verify its output.
330
331    Args:
332      verify_exit_fn: A function taking (status, output).
333      expected_logs: List of tuples, or None if output shouldn't be checked.
334          Tuple is (log prefix, log type, expected contents):
335          - log prefix: A program name, or 'stderr'.
336          - log type: 'INFO', 'ERROR', etc.
337          - expected: Can be the following:
338            - A string
339            - A callable, called with the logs as a single argument
340            - None, means don't check contents of log file
341      test_name: Name to pass to helper.
342      pass_logtostderr: Pass --logtostderr to the helper script if True.
343      use_absl_log_file: If True, call
344          logging.get_absl_handler().use_absl_log_file() before test_fn in
345          logging_functional_test_helper.
346      show_info_prefix: --showprefixforinfo value passed to the helper script.
347      call_dict_config: True if helper script should call
348          logging.config.dictConfig.
349      extra_args: Iterable of str (optional, defaults to ()) - extra arguments
350          to pass to the helper script.
351
352    Raises:
353      AssertionError: Assertion error when test fails.
354    """
355    args = ['--log_dir=%s' % self._log_dir]
356    if pass_logtostderr:
357      args.append('--logtostderr')
358    if not show_info_prefix:
359      args.append('--noshowprefixforinfo')
360    args += extra_args
361
362    # Execute helper in subprocess.
363    env = os.environ.copy()
364    env.update({
365        'TEST_NAME': test_name,
366        'USE_ABSL_LOG_FILE': '%d' % (use_absl_log_file,),
367        'CALL_DICT_CONFIG': '%d' % (call_dict_config,),
368    })
369    cmd = [self._get_helper()] + args
370
371    print('env: %s' % env, file=sys.stderr)
372    print('cmd: %s' % cmd, file=sys.stderr)
373    process = subprocess.Popen(
374        cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env,
375        universal_newlines=True)
376    output, _ = process.communicate()
377    status = process.returncode
378
379    # Verify exit status.
380    verify_exit_fn(status, output)
381
382    # Check outputs?
383    if expected_logs is None:
384      return
385
386    # Get list of log files.
387    logs = os.listdir(self._log_dir)
388    logs = fnmatch.filter(logs, '*.log.*')
389    logs.append('stderr')
390
391    # Look for a log matching each expected pattern.
392    matched = []
393    unmatched = []
394    unexpected = logs[:]
395    for log_prefix, log_type, expected in expected_logs:
396      # What pattern?
397      if log_prefix == 'stderr':
398        assert log_type is None
399        pattern = 'stderr'
400      else:
401        pattern = r'%s[.].*[.]log[.]%s[.][\d.-]*$' % (log_prefix, log_type)
402
403      # Is it there
404      for basename in logs:
405        if re.match(pattern, basename):
406          matched.append([expected, basename])
407          unexpected.remove(basename)
408          break
409      else:
410        unmatched.append(pattern)
411
412    # Mismatch?
413    errors = ''
414    if unmatched:
415      errors += 'The following log files were expected but not found: %s' % (
416          '\n '.join(unmatched))
417    if unexpected:
418      if errors:
419        errors += '\n'
420      errors += 'The following log files were not expected: %s' % (
421          '\n '.join(unexpected))
422    if errors:
423      raise AssertionError(errors)
424
425    # Compare contents of matches.
426    for (expected, basename) in matched:
427      if expected is None:
428        continue
429
430      if basename == 'stderr':
431        actual = output
432      else:
433        path = os.path.join(self._log_dir, basename)
434        with open(path, encoding='utf-8') as f:
435          actual = f.read()
436
437      if callable(expected):
438        try:
439          expected(actual)
440        except AssertionError:
441          print('expected_logs assertion failed, actual {} log:\n{}'.format(
442              basename, actual), file=sys.stderr)
443          raise
444      elif isinstance(expected, str):
445        self.assertMultiLineEqual(_munge_log(expected), _munge_log(actual),
446                                  '%s differs' % basename)
447      else:
448        self.fail(
449            'Invalid value found for expected logs: {}, type: {}'.format(
450                expected, type(expected)))
451
452  @parameterized.named_parameters(
453      ('', False),
454      ('logtostderr', True))
455  def test_py_logging(self, logtostderr):
456    # Python logging by default logs to stderr.
457    self._exec_test(
458        _verify_ok,
459        [['stderr', None, self._get_logs(logging.INFO)]],
460        pass_logtostderr=logtostderr)
461
462  def test_py_logging_use_absl_log_file(self):
463    # Python logging calling use_absl_log_file causes also log to files.
464    self._exec_test(
465        _verify_ok,
466        [['stderr', None, ''],
467         ['absl_log_file', 'INFO', self._get_logs(logging.INFO)]],
468        use_absl_log_file=True)
469
470  def test_py_logging_use_absl_log_file_logtostderr(self):
471    # Python logging asked to log to stderr even though use_absl_log_file
472    # is called.
473    self._exec_test(
474        _verify_ok,
475        [['stderr', None, self._get_logs(logging.INFO)]],
476        pass_logtostderr=True,
477        use_absl_log_file=True)
478
479  @parameterized.named_parameters(
480      ('', False),
481      ('logtostderr', True))
482  def test_py_logging_noshowprefixforinfo(self, logtostderr):
483    self._exec_test(
484        _verify_ok,
485        [['stderr', None, self._get_logs(logging.INFO,
486                                         include_info_prefix=False)]],
487        pass_logtostderr=logtostderr,
488        show_info_prefix=0)
489
490  def test_py_logging_noshowprefixforinfo_use_absl_log_file(self):
491    self._exec_test(
492        _verify_ok,
493        [['stderr', None, ''],
494         ['absl_log_file', 'INFO', self._get_logs(logging.INFO)]],
495        show_info_prefix=0,
496        use_absl_log_file=True)
497
498  def test_py_logging_noshowprefixforinfo_use_absl_log_file_logtostderr(self):
499    self._exec_test(
500        _verify_ok,
501        [['stderr', None, self._get_logs(logging.INFO,
502                                         include_info_prefix=False)]],
503        pass_logtostderr=True,
504        show_info_prefix=0,
505        use_absl_log_file=True)
506
507  def test_py_logging_noshowprefixforinfo_verbosity(self):
508    self._exec_test(
509        _verify_ok,
510        [['stderr', None, self._get_logs(logging.DEBUG)]],
511        pass_logtostderr=True,
512        show_info_prefix=0,
513        use_absl_log_file=True,
514        extra_args=['-v=1'])
515
516  def test_py_logging_fatal_main_thread_only(self):
517    self._exec_test(
518        _verify_fatal,
519        [['stderr', None, _get_fatal_log_expectation(
520            self, 'fatal_main_thread_only', False)]],
521        test_name='fatal_main_thread_only')
522
523  def test_py_logging_fatal_with_other_threads(self):
524    self._exec_test(
525        _verify_fatal,
526        [['stderr', None, _get_fatal_log_expectation(
527            self, 'fatal_with_other_threads', False)]],
528        test_name='fatal_with_other_threads')
529
530  def test_py_logging_fatal_non_main_thread(self):
531    self._exec_test(
532        _verify_fatal,
533        [['stderr', None, _get_fatal_log_expectation(
534            self, 'fatal_non_main_thread', False)]],
535        test_name='fatal_non_main_thread')
536
537  def test_py_logging_critical_non_absl(self):
538    self._exec_test(
539        _verify_ok,
540        [['stderr', None, _CRITICAL_DOWNGRADE_TO_ERROR_MESSAGE]],
541        test_name='critical_from_non_absl_logger')
542
543  def test_py_logging_skip_log_prefix(self):
544    self._exec_test(
545        _verify_ok,
546        [['stderr', None, '']],
547        test_name='register_frame_to_skip')
548
549  def test_py_logging_flush(self):
550    self._exec_test(
551        _verify_ok,
552        [['stderr', None, '']],
553        test_name='flush')
554
555  @parameterized.named_parameters(*_VERBOSITY_FLAG_TEST_PARAMETERS)
556  def test_py_logging_verbosity_stderr(self, verbosity):
557    """Tests -v/--verbosity flag with python logging to stderr."""
558    v_flag = '-v=%d' % verbosity
559    self._exec_test(
560        _verify_ok,
561        [['stderr', None, self._get_logs(verbosity)]],
562        extra_args=[v_flag])
563
564  @parameterized.named_parameters(*_VERBOSITY_FLAG_TEST_PARAMETERS)
565  def test_py_logging_verbosity_file(self, verbosity):
566    """Tests -v/--verbosity flag with Python logging to stderr."""
567    v_flag = '-v=%d' % verbosity
568    self._exec_test(
569        _verify_ok,
570        [['stderr', None, ''],
571         # When using python logging, it only creates a file named INFO,
572         # unlike C++ it also creates WARNING and ERROR files.
573         ['absl_log_file', 'INFO', self._get_logs(verbosity)]],
574        use_absl_log_file=True,
575        extra_args=[v_flag])
576
577  def test_stderrthreshold_py_logging(self):
578    """Tests --stderrthreshold."""
579
580    stderr_logs = '''\
581I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, debug log
582I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, info log
583W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, warning log
584E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, error log
585I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, info log
586W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, warning log
587E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, error log
588W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=warning, warning log
589E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=warning, error log
590E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=error, error log
591'''
592
593    expected_logs = [
594        ['stderr', None, stderr_logs],
595        ['absl_log_file', 'INFO', None],
596    ]
597    # Set verbosity to debug to test stderrthreshold == debug.
598    extra_args = ['-v=1']
599
600    self._exec_test(
601        _verify_ok,
602        expected_logs,
603        test_name='stderrthreshold',
604        extra_args=extra_args,
605        use_absl_log_file=True)
606
607  def test_std_logging_py_logging(self):
608    """Tests logs from std logging."""
609    stderr_logs = '''\
610I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std debug log
611I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std info log
612W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std warning log
613E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std error log
614'''
615    expected_logs = [['stderr', None, stderr_logs]]
616
617    extra_args = ['-v=1', '--logtostderr']
618    self._exec_test(
619        _verify_ok,
620        expected_logs,
621        test_name='std_logging',
622        extra_args=extra_args)
623
624  def test_bad_exc_info_py_logging(self):
625
626    def assert_stderr(stderr):
627      # The exact message differs among different Python versions. So it just
628      # asserts some certain information is there.
629      self.assertIn('Traceback (most recent call last):', stderr)
630      self.assertIn('IndexError', stderr)
631
632    expected_logs = [
633        ['stderr', None, assert_stderr],
634        ['absl_log_file', 'INFO', '']]
635
636    self._exec_test(
637        _verify_ok,
638        expected_logs,
639        test_name='bad_exc_info',
640        use_absl_log_file=True)
641
642  def test_verbosity_logger_levels_flag_ordering(self):
643    """Make sure last-specified flag wins."""
644
645    def assert_error_level_logged(stderr):
646      lines = stderr.splitlines()
647      for line in lines:
648        self.assertIn('std error log', line)
649
650    self._exec_test(
651        _verify_ok,
652        test_name='std_logging',
653        expected_logs=[('stderr', None, assert_error_level_logged)],
654        extra_args=['-v=1', '--logger_levels=:ERROR'])
655
656    def assert_debug_level_logged(stderr):
657      lines = stderr.splitlines()
658      for line in lines:
659        self.assertRegex(line, 'std (debug|info|warning|error) log')
660
661    self._exec_test(
662        _verify_ok,
663        test_name='std_logging',
664        expected_logs=[('stderr', None, assert_debug_level_logged)],
665        extra_args=['--logger_levels=:ERROR', '-v=1'])
666
667  def test_none_exc_info_py_logging(self):
668
669    expected_stderr = ''
670    expected_info = '''\
671I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] None exc_info
672'''
673    expected_info += 'NoneType: None\n'
674
675    expected_logs = [
676        ['stderr', None, expected_stderr],
677        ['absl_log_file', 'INFO', expected_info]]
678
679    self._exec_test(
680        _verify_ok,
681        expected_logs,
682        test_name='none_exc_info',
683        use_absl_log_file=True)
684
685  def test_unicode_py_logging(self):
686
687    def get_stderr_message(stderr, name):
688      match = re.search(
689          '-- begin {} --\n(.*)-- end {} --'.format(name, name),
690          stderr, re.MULTILINE | re.DOTALL)
691      self.assertTrue(
692          match, 'Cannot find stderr message for test {}'.format(name))
693      return match.group(1)
694
695    def assert_stderr(stderr):
696      """Verifies that it writes correct information to stderr for Python 3.
697
698      There are no unicode errors in Python 3.
699
700      Args:
701        stderr: the message from stderr.
702      """
703      # Successful logs:
704      for name in (
705          'unicode', 'unicode % unicode', 'bytes % bytes', 'unicode % bytes',
706          'bytes % unicode', 'unicode % iso8859-15', 'str % exception',
707          'str % exception'):
708        logging.info('name = %s', name)
709        self.assertEqual('', get_stderr_message(stderr, name))
710
711    expected_logs = [['stderr', None, assert_stderr]]
712
713    info_log = u'''\
714I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: Ch\u00e2tonnaye
715I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: Ch\u00e2tonnaye
716I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] b'G\\xc3\\xaete: b'Ch\\xc3\\xa2tonnaye''
717I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: b'Ch\\xc3\\xa2tonnaye'
718I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] b'G\\xc3\\xaete: Ch\u00e2tonnaye'
719I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: b'Ch\\xe2tonnaye'
720I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] exception: Ch\u00e2tonnaye
721'''
722    expected_logs.append(['absl_log_file', 'INFO', info_log])
723
724    self._exec_test(
725        _verify_ok,
726        expected_logs,
727        test_name='unicode',
728        use_absl_log_file=True)
729
730
731if __name__ == '__main__':
732  absltest.main()
733