| # Copyright 2017 The Abseil Authors. |
| # |
| # Licensed under the Apache License, Version 2.0 (the "License"); |
| # you may not use this file except in compliance with the License. |
| # You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, software |
| # distributed under the License is distributed on an "AS IS" BASIS, |
| # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| # See the License for the specific language governing permissions and |
| # limitations under the License. |
| |
| """Functional tests for absl.logging.""" |
| |
| import fnmatch |
| import os |
| import re |
| import shutil |
| import subprocess |
| import sys |
| import tempfile |
| |
| from absl import logging |
| from absl.testing import _bazelize_command |
| from absl.testing import absltest |
| from absl.testing import parameterized |
| |
| |
| _PY_VLOG3_LOG_MESSAGE = """\ |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:62] This line is VLOG level 3 |
| """ |
| |
| _PY_VLOG2_LOG_MESSAGE = """\ |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] This line is VLOG level 2 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] This line is log level 2 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:64] VLOG level 1, but only if VLOG level 2 is active |
| """ |
| |
| # VLOG1 is the same as DEBUG logs. |
| _PY_DEBUG_LOG_MESSAGE = """\ |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level 1 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level 1 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:66] This line is DEBUG |
| """ |
| |
| _PY_INFO_LOG_MESSAGE = """\ |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level 0 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level 0 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:70] Interesting Stuff\0 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:71] Interesting Stuff with Arguments: 42 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:73] Interesting Stuff with Dictionary |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times. |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times. |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times. |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times. |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:123] This should appear 5 times. |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:76] Info first 1 of 2 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:77] Info 1 (every 3) |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:76] Info first 2 of 2 |
| I1231 23:59:59.000000 12345 logging_functional_test_helper.py:77] Info 4 (every 3) |
| """ |
| |
| _PY_INFO_LOG_MESSAGE_NOPREFIX = """\ |
| This line is VLOG level 0 |
| This line is log level 0 |
| Interesting Stuff\0 |
| Interesting Stuff with Arguments: 42 |
| Interesting Stuff with Dictionary |
| This should appear 5 times. |
| This should appear 5 times. |
| This should appear 5 times. |
| This should appear 5 times. |
| This should appear 5 times. |
| Info first 1 of 2 |
| Info 1 (every 3) |
| Info first 2 of 2 |
| Info 4 (every 3) |
| """ |
| |
| _PY_WARNING_LOG_MESSAGE = """\ |
| W1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level -1 |
| W1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level -1 |
| W1231 23:59:59.000000 12345 logging_functional_test_helper.py:79] Worrying Stuff |
| W0000 23:59:59.000000 12345 logging_functional_test_helper.py:81] Warn first 1 of 2 |
| W0000 23:59:59.000000 12345 logging_functional_test_helper.py:82] Warn 1 (every 3) |
| W0000 23:59:59.000000 12345 logging_functional_test_helper.py:81] Warn first 2 of 2 |
| W0000 23:59:59.000000 12345 logging_functional_test_helper.py:82] Warn 4 (every 3) |
| """ |
| |
| if sys.version_info[0:2] == (3, 4): |
| _FAKE_ERROR_EXTRA_MESSAGE = """\ |
| Traceback (most recent call last): |
| File "logging_functional_test_helper.py", line 456, in _test_do_logging |
| raise OSError('Fake Error') |
| """ |
| else: |
| _FAKE_ERROR_EXTRA_MESSAGE = '' |
| |
| _PY_ERROR_LOG_MESSAGE = """\ |
| E1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is VLOG level -2 |
| E1231 23:59:59.000000 12345 logging_functional_test_helper.py:65] This line is log level -2 |
| E1231 23:59:59.000000 12345 logging_functional_test_helper.py:87] An Exception %s |
| Traceback (most recent call last): |
| File "logging_functional_test_helper.py", line 456, in _test_do_logging |
| raise OSError('Fake Error') |
| OSError: Fake Error |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Once more, just because |
| Traceback (most recent call last): |
| File "./logging_functional_test_helper.py", line 78, in _test_do_logging |
| raise OSError('Fake Error') |
| OSError: Fake Error |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Exception 2 %s |
| Traceback (most recent call last): |
| File "logging_functional_test_helper.py", line 456, in _test_do_logging |
| raise OSError('Fake Error') |
| OSError: Fake Error |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Non-exception |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] Exception 3 |
| Traceback (most recent call last): |
| File "logging_functional_test_helper.py", line 456, in _test_do_logging |
| raise OSError('Fake Error') |
| OSError: Fake Error |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] No traceback |
| {fake_error_extra}OSError: Fake Error |
| E1231 23:59:59.000000 12345 logging_functional_test_helper.py:90] Alarming Stuff |
| E0000 23:59:59.000000 12345 logging_functional_test_helper.py:92] Error first 1 of 2 |
| E0000 23:59:59.000000 12345 logging_functional_test_helper.py:93] Error 1 (every 3) |
| E0000 23:59:59.000000 12345 logging_functional_test_helper.py:92] Error first 2 of 2 |
| E0000 23:59:59.000000 12345 logging_functional_test_helper.py:93] Error 4 (every 3) |
| """.format(fake_error_extra=_FAKE_ERROR_EXTRA_MESSAGE) |
| |
| |
| _CRITICAL_DOWNGRADE_TO_ERROR_MESSAGE = """\ |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] CRITICAL - A critical message |
| """ |
| |
| |
| _VERBOSITY_FLAG_TEST_PARAMETERS = ( |
| ('fatal', logging.FATAL), |
| ('error', logging.ERROR), |
| ('warning', logging.WARN), |
| ('info', logging.INFO), |
| ('debug', logging.DEBUG), |
| ('vlog1', 1), |
| ('vlog2', 2), |
| ('vlog3', 3)) |
| |
| |
| def _get_fatal_log_expectation(testcase, message, include_stacktrace): |
| """Returns the expectation for fatal logging tests. |
| |
| Args: |
| testcase: The TestCase instance. |
| message: The extra fatal logging message. |
| include_stacktrace: Whether or not to include stacktrace. |
| |
| Returns: |
| A callable, the expectation for fatal logging tests. It will be passed to |
| FunctionalTest._exec_test as third items in the expected_logs list. |
| See _exec_test's docstring for more information. |
| """ |
| def assert_logs(logs): |
| if os.name == 'nt': |
| # On Windows, it also dumps extra information at the end, something like: |
| # This application has requested the Runtime to terminate it in an |
| # unusual way. Please contact the application's support team for more |
| # information. |
| logs = '\n'.join(logs.split('\n')[:-3]) |
| format_string = ( |
| 'F1231 23:59:59.000000 12345 logging_functional_test_helper.py:175] ' |
| '%s message\n') |
| expected_logs = format_string % message |
| if include_stacktrace: |
| expected_logs += 'Stack trace:\n' |
| faulthandler_start = 'Fatal Python error: Aborted' |
| testcase.assertIn(faulthandler_start, logs) |
| log_message = logs.split(faulthandler_start)[0] |
| testcase.assertEqual(_munge_log(expected_logs), _munge_log(log_message)) |
| |
| return assert_logs |
| |
| |
| def _munge_log(buf): |
| """Remove timestamps, thread ids, filenames and line numbers from logs.""" |
| |
| # Remove all messages produced before the output to be tested. |
| buf = re.sub(r'(?:.|\n)*START OF TEST HELPER LOGS: IGNORE PREVIOUS.\n', |
| r'', |
| buf) |
| |
| # Greeting |
| buf = re.sub(r'(?m)^Log file created at: .*\n', |
| '', |
| buf) |
| buf = re.sub(r'(?m)^Running on machine: .*\n', |
| '', |
| buf) |
| buf = re.sub(r'(?m)^Binary: .*\n', |
| '', |
| buf) |
| buf = re.sub(r'(?m)^Log line format: .*\n', |
| '', |
| buf) |
| |
| # Verify thread id is logged as a non-negative quantity. |
| matched = re.match(r'(?m)^(\w)(\d\d\d\d \d\d:\d\d:\d\d\.\d\d\d\d\d\d) ' |
| r'([ ]*-?[0-9a-fA-f]+ )?([a-zA-Z<][\w._<>-]+):(\d+)', |
| buf) |
| if matched: |
| threadid = matched.group(3) |
| if int(threadid) < 0: |
| raise AssertionError("Negative threadid '%s' in '%s'" % (threadid, buf)) |
| |
| # Timestamp |
| buf = re.sub(r'(?m)' + logging.ABSL_LOGGING_PREFIX_REGEX, |
| r'\g<severity>0000 00:00:00.000000 12345 \g<filename>:123', |
| buf) |
| |
| # Traceback |
| buf = re.sub(r'(?m)^ File "(.*/)?([^"/]+)", line (\d+),', |
| r' File "\g<2>", line 456,', |
| buf) |
| |
| # Stack trace is too complicated for re, just assume it extends to end of |
| # output |
| buf = re.sub(r'(?sm)^Stack trace:\n.*', |
| r'Stack trace:\n', |
| buf) |
| buf = re.sub(r'(?sm)^\*\*\* Signal 6 received by PID.*\n.*', |
| r'Stack trace:\n', |
| buf) |
| buf = re.sub((r'(?sm)^\*\*\* ([A-Z]+) received by PID (\d+) ' |
| r'\(TID 0x([0-9a-f]+)\)' |
| r'( from PID \d+)?; stack trace: \*\*\*\n.*'), |
| r'Stack trace:\n', |
| buf) |
| buf = re.sub(r'(?sm)^\*\*\* Check failure stack trace: \*\*\*\n.*', |
| r'Stack trace:\n', |
| buf) |
| |
| if os.name == 'nt': |
| # On windows, we calls Python interpreter explicitly, so the file names |
| # include the full path. Strip them. |
| buf = re.sub(r'( File ").*(logging_functional_test_helper\.py", line )', |
| r'\1\2', |
| buf) |
| |
| return buf |
| |
| |
| def _verify_status(expected, actual, output): |
| if expected != actual: |
| raise AssertionError( |
| 'Test exited with unexpected status code %d (expected %d). ' |
| 'Output was:\n%s' % (actual, expected, output)) |
| |
| |
| def _verify_ok(status, output): |
| """Check that helper exited with no errors.""" |
| _verify_status(0, status, output) |
| |
| |
| def _verify_fatal(status, output): |
| """Check that helper died as expected.""" |
| # os.abort generates a SIGABRT signal (-6). On Windows, the process |
| # immediately returns an exit code of 3. |
| # See https://docs.python.org/3.6/library/os.html#os.abort. |
| expected_exit_code = 3 if os.name == 'nt' else -6 |
| _verify_status(expected_exit_code, status, output) |
| |
| |
| def _verify_assert(status, output): |
| """.Check that helper failed with assertion.""" |
| _verify_status(1, status, output) |
| |
| |
| class FunctionalTest(parameterized.TestCase): |
| """Functional tests using the logging_functional_test_helper script.""" |
| |
| def _get_helper(self): |
| helper_name = 'absl/logging/tests/logging_functional_test_helper' |
| return _bazelize_command.get_executable_path(helper_name) |
| |
| def _get_logs(self, |
| verbosity, |
| include_info_prefix=True): |
| logs = [] |
| if verbosity >= 3: |
| logs.append(_PY_VLOG3_LOG_MESSAGE) |
| if verbosity >= 2: |
| logs.append(_PY_VLOG2_LOG_MESSAGE) |
| if verbosity >= logging.DEBUG: |
| logs.append(_PY_DEBUG_LOG_MESSAGE) |
| |
| if verbosity >= logging.INFO: |
| if include_info_prefix: |
| logs.append(_PY_INFO_LOG_MESSAGE) |
| else: |
| logs.append(_PY_INFO_LOG_MESSAGE_NOPREFIX) |
| if verbosity >= logging.WARN: |
| logs.append(_PY_WARNING_LOG_MESSAGE) |
| if verbosity >= logging.ERROR: |
| logs.append(_PY_ERROR_LOG_MESSAGE) |
| |
| expected_logs = ''.join(logs) |
| expected_logs = expected_logs.replace( |
| "<type 'exceptions.OSError'>", "<class 'OSError'>") |
| return expected_logs |
| |
| def setUp(self): |
| super(FunctionalTest, self).setUp() |
| self._log_dir = tempfile.mkdtemp(dir=absltest.TEST_TMPDIR.value) |
| |
| def tearDown(self): |
| shutil.rmtree(self._log_dir) |
| super(FunctionalTest, self).tearDown() |
| |
| def _exec_test(self, |
| verify_exit_fn, |
| expected_logs, |
| test_name='do_logging', |
| pass_logtostderr=False, |
| use_absl_log_file=False, |
| show_info_prefix=1, |
| call_dict_config=False, |
| extra_args=()): |
| """Execute the helper script and verify its output. |
| |
| Args: |
| verify_exit_fn: A function taking (status, output). |
| expected_logs: List of tuples, or None if output shouldn't be checked. |
| Tuple is (log prefix, log type, expected contents): |
| - log prefix: A program name, or 'stderr'. |
| - log type: 'INFO', 'ERROR', etc. |
| - expected: Can be the following: |
| - A string |
| - A callable, called with the logs as a single argument |
| - None, means don't check contents of log file |
| test_name: Name to pass to helper. |
| pass_logtostderr: Pass --logtostderr to the helper script if True. |
| use_absl_log_file: If True, call |
| logging.get_absl_handler().use_absl_log_file() before test_fn in |
| logging_functional_test_helper. |
| show_info_prefix: --showprefixforinfo value passed to the helper script. |
| call_dict_config: True if helper script should call |
| logging.config.dictConfig. |
| extra_args: Iterable of str (optional, defaults to ()) - extra arguments |
| to pass to the helper script. |
| |
| Raises: |
| AssertionError: Assertion error when test fails. |
| """ |
| args = ['--log_dir=%s' % self._log_dir] |
| if pass_logtostderr: |
| args.append('--logtostderr') |
| if not show_info_prefix: |
| args.append('--noshowprefixforinfo') |
| args += extra_args |
| |
| # Execute helper in subprocess. |
| env = os.environ.copy() |
| env.update({ |
| 'TEST_NAME': test_name, |
| 'USE_ABSL_LOG_FILE': '%d' % (use_absl_log_file,), |
| 'CALL_DICT_CONFIG': '%d' % (call_dict_config,), |
| }) |
| cmd = [self._get_helper()] + args |
| |
| print('env: %s' % env, file=sys.stderr) |
| print('cmd: %s' % cmd, file=sys.stderr) |
| process = subprocess.Popen( |
| cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env, |
| universal_newlines=True) |
| output, _ = process.communicate() |
| status = process.returncode |
| |
| # Verify exit status. |
| verify_exit_fn(status, output) |
| |
| # Check outputs? |
| if expected_logs is None: |
| return |
| |
| # Get list of log files. |
| logs = os.listdir(self._log_dir) |
| logs = fnmatch.filter(logs, '*.log.*') |
| logs.append('stderr') |
| |
| # Look for a log matching each expected pattern. |
| matched = [] |
| unmatched = [] |
| unexpected = logs[:] |
| for log_prefix, log_type, expected in expected_logs: |
| # What pattern? |
| if log_prefix == 'stderr': |
| assert log_type is None |
| pattern = 'stderr' |
| else: |
| pattern = r'%s[.].*[.]log[.]%s[.][\d.-]*$' % (log_prefix, log_type) |
| |
| # Is it there |
| for basename in logs: |
| if re.match(pattern, basename): |
| matched.append([expected, basename]) |
| unexpected.remove(basename) |
| break |
| else: |
| unmatched.append(pattern) |
| |
| # Mismatch? |
| errors = '' |
| if unmatched: |
| errors += 'The following log files were expected but not found: %s' % ( |
| '\n '.join(unmatched)) |
| if unexpected: |
| if errors: |
| errors += '\n' |
| errors += 'The following log files were not expected: %s' % ( |
| '\n '.join(unexpected)) |
| if errors: |
| raise AssertionError(errors) |
| |
| # Compare contents of matches. |
| for (expected, basename) in matched: |
| if expected is None: |
| continue |
| |
| if basename == 'stderr': |
| actual = output |
| else: |
| path = os.path.join(self._log_dir, basename) |
| with open(path, encoding='utf-8') as f: |
| actual = f.read() |
| |
| if callable(expected): |
| try: |
| expected(actual) |
| except AssertionError: |
| print('expected_logs assertion failed, actual {} log:\n{}'.format( |
| basename, actual), file=sys.stderr) |
| raise |
| elif isinstance(expected, str): |
| self.assertMultiLineEqual(_munge_log(expected), _munge_log(actual), |
| '%s differs' % basename) |
| else: |
| self.fail( |
| 'Invalid value found for expected logs: {}, type: {}'.format( |
| expected, type(expected))) |
| |
| @parameterized.named_parameters( |
| ('', False), |
| ('logtostderr', True)) |
| def test_py_logging(self, logtostderr): |
| # Python logging by default logs to stderr. |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(logging.INFO)]], |
| pass_logtostderr=logtostderr) |
| |
| def test_py_logging_use_absl_log_file(self): |
| # Python logging calling use_absl_log_file causes also log to files. |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, ''], |
| ['absl_log_file', 'INFO', self._get_logs(logging.INFO)]], |
| use_absl_log_file=True) |
| |
| def test_py_logging_use_absl_log_file_logtostderr(self): |
| # Python logging asked to log to stderr even though use_absl_log_file |
| # is called. |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(logging.INFO)]], |
| pass_logtostderr=True, |
| use_absl_log_file=True) |
| |
| @parameterized.named_parameters( |
| ('', False), |
| ('logtostderr', True)) |
| def test_py_logging_noshowprefixforinfo(self, logtostderr): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(logging.INFO, |
| include_info_prefix=False)]], |
| pass_logtostderr=logtostderr, |
| show_info_prefix=0) |
| |
| def test_py_logging_noshowprefixforinfo_use_absl_log_file(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, ''], |
| ['absl_log_file', 'INFO', self._get_logs(logging.INFO)]], |
| show_info_prefix=0, |
| use_absl_log_file=True) |
| |
| def test_py_logging_noshowprefixforinfo_use_absl_log_file_logtostderr(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(logging.INFO, |
| include_info_prefix=False)]], |
| pass_logtostderr=True, |
| show_info_prefix=0, |
| use_absl_log_file=True) |
| |
| def test_py_logging_noshowprefixforinfo_verbosity(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(logging.DEBUG)]], |
| pass_logtostderr=True, |
| show_info_prefix=0, |
| use_absl_log_file=True, |
| extra_args=['-v=1']) |
| |
| def test_py_logging_fatal_main_thread_only(self): |
| self._exec_test( |
| _verify_fatal, |
| [['stderr', None, _get_fatal_log_expectation( |
| self, 'fatal_main_thread_only', False)]], |
| test_name='fatal_main_thread_only') |
| |
| def test_py_logging_fatal_with_other_threads(self): |
| self._exec_test( |
| _verify_fatal, |
| [['stderr', None, _get_fatal_log_expectation( |
| self, 'fatal_with_other_threads', False)]], |
| test_name='fatal_with_other_threads') |
| |
| def test_py_logging_fatal_non_main_thread(self): |
| self._exec_test( |
| _verify_fatal, |
| [['stderr', None, _get_fatal_log_expectation( |
| self, 'fatal_non_main_thread', False)]], |
| test_name='fatal_non_main_thread') |
| |
| def test_py_logging_critical_non_absl(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, _CRITICAL_DOWNGRADE_TO_ERROR_MESSAGE]], |
| test_name='critical_from_non_absl_logger') |
| |
| def test_py_logging_skip_log_prefix(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, '']], |
| test_name='register_frame_to_skip') |
| |
| def test_py_logging_flush(self): |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, '']], |
| test_name='flush') |
| |
| @parameterized.named_parameters(*_VERBOSITY_FLAG_TEST_PARAMETERS) |
| def test_py_logging_verbosity_stderr(self, verbosity): |
| """Tests -v/--verbosity flag with python logging to stderr.""" |
| v_flag = '-v=%d' % verbosity |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, self._get_logs(verbosity)]], |
| extra_args=[v_flag]) |
| |
| @parameterized.named_parameters(*_VERBOSITY_FLAG_TEST_PARAMETERS) |
| def test_py_logging_verbosity_file(self, verbosity): |
| """Tests -v/--verbosity flag with Python logging to stderr.""" |
| v_flag = '-v=%d' % verbosity |
| self._exec_test( |
| _verify_ok, |
| [['stderr', None, ''], |
| # When using python logging, it only creates a file named INFO, |
| # unlike C++ it also creates WARNING and ERROR files. |
| ['absl_log_file', 'INFO', self._get_logs(verbosity)]], |
| use_absl_log_file=True, |
| extra_args=[v_flag]) |
| |
| def test_stderrthreshold_py_logging(self): |
| """Tests --stderrthreshold.""" |
| |
| stderr_logs = '''\ |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, debug log |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, info log |
| W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, warning log |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=debug, error log |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, info log |
| W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, warning log |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=info, error log |
| W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=warning, warning log |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=warning, error log |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=error, error log |
| ''' |
| |
| expected_logs = [ |
| ['stderr', None, stderr_logs], |
| ['absl_log_file', 'INFO', None], |
| ] |
| # Set verbosity to debug to test stderrthreshold == debug. |
| extra_args = ['-v=1'] |
| |
| self._exec_test( |
| _verify_ok, |
| expected_logs, |
| test_name='stderrthreshold', |
| extra_args=extra_args, |
| use_absl_log_file=True) |
| |
| def test_std_logging_py_logging(self): |
| """Tests logs from std logging.""" |
| stderr_logs = '''\ |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std debug log |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std info log |
| W0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std warning log |
| E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] std error log |
| ''' |
| expected_logs = [['stderr', None, stderr_logs]] |
| |
| extra_args = ['-v=1', '--logtostderr'] |
| self._exec_test( |
| _verify_ok, |
| expected_logs, |
| test_name='std_logging', |
| extra_args=extra_args) |
| |
| def test_bad_exc_info_py_logging(self): |
| |
| def assert_stderr(stderr): |
| # The exact message differs among different Python versions. So it just |
| # asserts some certain information is there. |
| self.assertIn('Traceback (most recent call last):', stderr) |
| self.assertIn('IndexError', stderr) |
| |
| expected_logs = [ |
| ['stderr', None, assert_stderr], |
| ['absl_log_file', 'INFO', '']] |
| |
| self._exec_test( |
| _verify_ok, |
| expected_logs, |
| test_name='bad_exc_info', |
| use_absl_log_file=True) |
| |
| def test_verbosity_logger_levels_flag_ordering(self): |
| """Make sure last-specified flag wins.""" |
| |
| def assert_error_level_logged(stderr): |
| lines = stderr.splitlines() |
| for line in lines: |
| self.assertIn('std error log', line) |
| |
| self._exec_test( |
| _verify_ok, |
| test_name='std_logging', |
| expected_logs=[('stderr', None, assert_error_level_logged)], |
| extra_args=['-v=1', '--logger_levels=:ERROR']) |
| |
| def assert_debug_level_logged(stderr): |
| lines = stderr.splitlines() |
| for line in lines: |
| self.assertRegex(line, 'std (debug|info|warning|error) log') |
| |
| self._exec_test( |
| _verify_ok, |
| test_name='std_logging', |
| expected_logs=[('stderr', None, assert_debug_level_logged)], |
| extra_args=['--logger_levels=:ERROR', '-v=1']) |
| |
| def test_none_exc_info_py_logging(self): |
| |
| expected_stderr = '' |
| expected_info = '''\ |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] None exc_info |
| ''' |
| expected_info += 'NoneType: None\n' |
| |
| expected_logs = [ |
| ['stderr', None, expected_stderr], |
| ['absl_log_file', 'INFO', expected_info]] |
| |
| self._exec_test( |
| _verify_ok, |
| expected_logs, |
| test_name='none_exc_info', |
| use_absl_log_file=True) |
| |
| def test_unicode_py_logging(self): |
| |
| def get_stderr_message(stderr, name): |
| match = re.search( |
| '-- begin {} --\n(.*)-- end {} --'.format(name, name), |
| stderr, re.MULTILINE | re.DOTALL) |
| self.assertTrue( |
| match, 'Cannot find stderr message for test {}'.format(name)) |
| return match.group(1) |
| |
| def assert_stderr(stderr): |
| """Verifies that it writes correct information to stderr for Python 3. |
| |
| There are no unicode errors in Python 3. |
| |
| Args: |
| stderr: the message from stderr. |
| """ |
| # Successful logs: |
| for name in ( |
| 'unicode', 'unicode % unicode', 'bytes % bytes', 'unicode % bytes', |
| 'bytes % unicode', 'unicode % iso8859-15', 'str % exception', |
| 'str % exception'): |
| logging.info('name = %s', name) |
| self.assertEqual('', get_stderr_message(stderr, name)) |
| |
| expected_logs = [['stderr', None, assert_stderr]] |
| |
| info_log = u'''\ |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: Ch\u00e2tonnaye |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: Ch\u00e2tonnaye |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] b'G\\xc3\\xaete: b'Ch\\xc3\\xa2tonnaye'' |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: b'Ch\\xc3\\xa2tonnaye' |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] b'G\\xc3\\xaete: Ch\u00e2tonnaye' |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] G\u00eete: b'Ch\\xe2tonnaye' |
| I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] exception: Ch\u00e2tonnaye |
| ''' |
| expected_logs.append(['absl_log_file', 'INFO', info_log]) |
| |
| self._exec_test( |
| _verify_ok, |
| expected_logs, |
| test_name='unicode', |
| use_absl_log_file=True) |
| |
| |
| if __name__ == '__main__': |
| absltest.main() |
