diff options
author | Yilei Yang <yileiyang@google.com> | 2017-09-19 14:25:01 -0700 |
---|---|---|
committer | Yilei Yang <yileiyang@google.com> | 2017-09-19 14:25:01 -0700 |
commit | 1c6972eef4d4dc774fa50f29248f776fa6628e9e (patch) | |
tree | 49f251967b459d7ec3c72042d132b77adb7d1b1a /absl/logging/tests | |
download | absl-py-1c6972eef4d4dc774fa50f29248f776fa6628e9e.tar.gz |
Initial commit: Abseil Python Common Libraries.
Diffstat (limited to 'absl/logging/tests')
-rw-r--r-- | absl/logging/tests/__init__.py | 13 | ||||
-rw-r--r-- | absl/logging/tests/converter_test.py | 135 | ||||
-rw-r--r-- | absl/logging/tests/log_before_import_test.py | 88 | ||||
-rwxr-xr-x | absl/logging/tests/logging_functional_test.py | 762 | ||||
-rwxr-xr-x | absl/logging/tests/logging_functional_test_helper.py | 302 | ||||
-rw-r--r-- | absl/logging/tests/logging_test.py | 734 | ||||
-rw-r--r-- | absl/logging/tests/verbosity_flag_test.py | 58 |
7 files changed, 2092 insertions, 0 deletions
diff --git a/absl/logging/tests/__init__.py b/absl/logging/tests/__init__.py new file mode 100644 index 0000000..a3bd1cd --- /dev/null +++ b/absl/logging/tests/__init__.py @@ -0,0 +1,13 @@ +# 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. diff --git a/absl/logging/tests/converter_test.py b/absl/logging/tests/converter_test.py new file mode 100644 index 0000000..bdc893a --- /dev/null +++ b/absl/logging/tests/converter_test.py @@ -0,0 +1,135 @@ +# 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. + +"""Tests for converter.py.""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import logging + +from absl import logging as absl_logging +from absl.logging import converter +from absl.testing import absltest + + +class ConverterTest(absltest.TestCase): + """Tests the converter module.""" + + def test_absl_to_cpp(self): + self.assertEqual(0, converter.absl_to_cpp(absl_logging.DEBUG)) + self.assertEqual(0, converter.absl_to_cpp(absl_logging.INFO)) + self.assertEqual(1, converter.absl_to_cpp(absl_logging.WARN)) + self.assertEqual(2, converter.absl_to_cpp(absl_logging.ERROR)) + self.assertEqual(3, converter.absl_to_cpp(absl_logging.FATAL)) + + with self.assertRaises(TypeError): + converter.absl_to_cpp('') + + def test_absl_to_standard(self): + self.assertEqual( + logging.DEBUG, converter.absl_to_standard(absl_logging.DEBUG)) + self.assertEqual( + logging.INFO, converter.absl_to_standard(absl_logging.INFO)) + self.assertEqual( + logging.WARNING, converter.absl_to_standard(absl_logging.WARN)) + self.assertEqual( + logging.WARN, converter.absl_to_standard(absl_logging.WARN)) + self.assertEqual( + logging.ERROR, converter.absl_to_standard(absl_logging.ERROR)) + self.assertEqual( + logging.FATAL, converter.absl_to_standard(absl_logging.FATAL)) + self.assertEqual( + logging.CRITICAL, converter.absl_to_standard(absl_logging.FATAL)) + # vlog levels. + self.assertEqual(9, converter.absl_to_standard(2)) + self.assertEqual(8, converter.absl_to_standard(3)) + + with self.assertRaises(TypeError): + converter.absl_to_standard('') + + def test_standard_to_absl(self): + self.assertEqual( + absl_logging.DEBUG, converter.standard_to_absl(logging.DEBUG)) + self.assertEqual( + absl_logging.INFO, converter.standard_to_absl(logging.INFO)) + self.assertEqual( + absl_logging.WARN, converter.standard_to_absl(logging.WARN)) + self.assertEqual( + absl_logging.WARN, converter.standard_to_absl(logging.WARNING)) + self.assertEqual( + absl_logging.ERROR, converter.standard_to_absl(logging.ERROR)) + self.assertEqual( + absl_logging.FATAL, converter.standard_to_absl(logging.FATAL)) + self.assertEqual( + absl_logging.FATAL, converter.standard_to_absl(logging.CRITICAL)) + # vlog levels. + self.assertEqual(2, converter.standard_to_absl(logging.DEBUG - 1)) + self.assertEqual(3, converter.standard_to_absl(logging.DEBUG - 2)) + + with self.assertRaises(TypeError): + converter.standard_to_absl('') + + def test_standard_to_cpp(self): + self.assertEqual(0, converter.standard_to_cpp(logging.DEBUG)) + self.assertEqual(0, converter.standard_to_cpp(logging.INFO)) + self.assertEqual(1, converter.standard_to_cpp(logging.WARN)) + self.assertEqual(1, converter.standard_to_cpp(logging.WARNING)) + self.assertEqual(2, converter.standard_to_cpp(logging.ERROR)) + self.assertEqual(3, converter.standard_to_cpp(logging.FATAL)) + self.assertEqual(3, converter.standard_to_cpp(logging.CRITICAL)) + + with self.assertRaises(TypeError): + converter.standard_to_cpp('') + + def test_get_initial_for_level(self): + self.assertEqual('F', converter.get_initial_for_level(logging.CRITICAL)) + self.assertEqual('E', converter.get_initial_for_level(logging.ERROR)) + self.assertEqual('W', converter.get_initial_for_level(logging.WARNING)) + self.assertEqual('I', converter.get_initial_for_level(logging.INFO)) + self.assertEqual('I', converter.get_initial_for_level(logging.DEBUG)) + self.assertEqual('I', converter.get_initial_for_level(logging.NOTSET)) + + self.assertEqual('F', converter.get_initial_for_level(51)) + self.assertEqual('E', converter.get_initial_for_level(49)) + self.assertEqual('E', converter.get_initial_for_level(41)) + self.assertEqual('W', converter.get_initial_for_level(39)) + self.assertEqual('W', converter.get_initial_for_level(31)) + self.assertEqual('I', converter.get_initial_for_level(29)) + self.assertEqual('I', converter.get_initial_for_level(21)) + self.assertEqual('I', converter.get_initial_for_level(19)) + self.assertEqual('I', converter.get_initial_for_level(11)) + self.assertEqual('I', converter.get_initial_for_level(9)) + self.assertEqual('I', converter.get_initial_for_level(1)) + self.assertEqual('I', converter.get_initial_for_level(-1)) + + def test_string_to_standard(self): + self.assertEqual(logging.DEBUG, converter.string_to_standard('debug')) + self.assertEqual(logging.INFO, converter.string_to_standard('info')) + self.assertEqual(logging.WARNING, converter.string_to_standard('warn')) + self.assertEqual(logging.WARNING, converter.string_to_standard('warning')) + self.assertEqual(logging.ERROR, converter.string_to_standard('error')) + self.assertEqual(logging.CRITICAL, converter.string_to_standard('fatal')) + + self.assertEqual(logging.DEBUG, converter.string_to_standard('DEBUG')) + self.assertEqual(logging.INFO, converter.string_to_standard('INFO')) + self.assertEqual(logging.WARNING, converter.string_to_standard('WARN')) + self.assertEqual(logging.WARNING, converter.string_to_standard('WARNING')) + self.assertEqual(logging.ERROR, converter.string_to_standard('ERROR')) + self.assertEqual(logging.CRITICAL, converter.string_to_standard('FATAL')) + + +if __name__ == '__main__': + absltest.main() diff --git a/absl/logging/tests/log_before_import_test.py b/absl/logging/tests/log_before_import_test.py new file mode 100644 index 0000000..d1ae0a7 --- /dev/null +++ b/absl/logging/tests/log_before_import_test.py @@ -0,0 +1,88 @@ +# 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. + +"""Test of logging behavior before app.run(), aka flag and logging init().""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import io +import re + +from absl import logging +from absl.testing import absltest +import mock + +# We do this before our library imports in order to catch any Python stderr +# output they may generate. We don't want them to; capture and check. +fake_stderr_type = io.BytesIO if bytes is str else io.StringIO + +logging.get_verbosity() # Access --verbosity before flag parsing. +# Access --logtostderr before flag parsing. +logging.get_absl_handler().use_absl_log_file() + + +class Error(Exception): + pass + + +# Pre-initialization (aka "import" / __main__ time) test. Checked below. +with mock.patch('sys.stderr', new=fake_stderr_type()) as pre_init_mock_stderr: + # Trigger the notice to stderr once. infos and above go to stderr. + logging.debug('Debug message at parse time.') + logging.info('Info message at parse time.') + logging.error('Error message at parse time.') + logging.warning('Warning message at parse time.') + try: + raise Error('Exception reason.') + except Error: + logging.exception('Exception message at parse time.') + + +class LoggingInitWarningTest(absltest.TestCase): + + def test_captured_pre_init_warnings(self): + captured_stderr = pre_init_mock_stderr.getvalue() + self.assertNotIn('Debug message at parse time.', captured_stderr) + self.assertNotIn('Info message at parse time.', captured_stderr) + + traceback_re = re.compile( + r'\nTraceback \(most recent call last\):.*?Error: Exception reason.', + re.MULTILINE | re.DOTALL) + if not traceback_re.search(captured_stderr): + self.fail( + 'Cannot find traceback message from logging.exception ' + 'in stderr:\n{}'.format(captured_stderr)) + # Remove the traceback so the rest of the stderr is deterministic. + captured_stderr = traceback_re.sub('', captured_stderr) + captured_stderr_lines = captured_stderr.splitlines() + self.assertLen(captured_stderr_lines, 4) + self.assertIn('Logging before flag parsing goes to stderr', + captured_stderr_lines[0]) + self.assertIn('Error message at parse time.', captured_stderr_lines[1]) + self.assertIn('Warning message at parse time.', captured_stderr_lines[2]) + self.assertIn('Exception message at parse time.', captured_stderr_lines[3]) + + def test_no_more_warnings(self): + with mock.patch('sys.stderr', new=fake_stderr_type()) as mock_stderr: + self.assertMultiLineEqual('', mock_stderr.getvalue()) + logging.warning('Hello. hello. hello. Is there anybody out there?') + self.assertNotIn('Logging before flag parsing goes to stderr', + mock_stderr.getvalue()) + logging.info('A major purpose of this executable is merely not to crash.') + + +if __name__ == '__main__': + absltest.main() # This calls the app.run() init equivalent. diff --git a/absl/logging/tests/logging_functional_test.py b/absl/logging/tests/logging_functional_test.py new file mode 100755 index 0000000..af36d23 --- /dev/null +++ b/absl/logging/tests/logging_functional_test.py @@ -0,0 +1,762 @@ +# 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.""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import fnmatch +import os +import re +import shutil +import subprocess +import sys +import tempfile + +from absl import flags +from absl import logging +from absl.testing import _bazelize_command +from absl.testing import absltest +from absl.testing import parameterized +import six + + +FLAGS = flags.FLAGS + + +_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 +""" + +# 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: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 +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' + if six.PY3: + 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): + return _bazelize_command.get_executable_path( + os.path.join(os.path.dirname(__file__), + 'logging_functional_test_helper')) + 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) + if six.PY3: + # In Python 3 class types are represented a bit differently + expected_logs = expected_logs.replace( + "<type 'exceptions.OSError'>", "<class 'OSError'>") + return expected_logs + + def setUp(self): + self._log_dir = tempfile.mkdtemp(dir=FLAGS.test_tmpdir) + + def tearDown(self): + shutil.rmtree(self._log_dir) + + 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, + 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 followings: + - 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. + 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,), + }) + 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) + if six.PY2: + f = open(path) + else: + f = open(path, encoding='utf-8') + with 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, warn 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, warn 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=warn, warn log +E0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] FLAGS.stderrthreshold=warn, 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 warn 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_none_exc_info_py_logging(self): + + if six.PY2: + expected_stderr = '' + expected_info = '''\ +I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] None exc_info +None +''' + else: + if sys.version_info[0:2] == (3, 4): + # Python 3.4 is different. + def expected_stderr(stderr): + regex = r'''--- Logging error --- +Traceback \(most recent call last\): +.* +Message: 'None exc_info' +Arguments: \(\)''' + if not re.search(regex, stderr, flags=re.DOTALL | re.MULTILINE): + self.fail('Cannot find regex "%s" in stderr:\n%s' % (regex, stderr)) + expected_info = '' + else: + expected_stderr = '' + expected_info = '''\ +I0000 00:00:00.000000 12345 logging_functional_test_helper.py:123] None exc_info +NoneType: None +''' + + 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_python2(stderr): + """Verifies that it writes correct information to stderr for Python 2. + + For unicode errors, it logs the exception with a stack trace to stderr. + + Args: + stderr: the message from stderr. + """ + # Successful logs: + for name in ('unicode', 'unicode % unicode', 'bytes % bytes'): + self.assertEqual('', get_stderr_message(stderr, name)) + + # UnicodeDecodeError errors: + for name in ( + 'unicode % bytes', 'bytes % unicode', 'unicode % iso8859-15'): + self.assertIn('UnicodeDecodeError', + get_stderr_message(stderr, name)) + self.assertIn('Traceback (most recent call last):', + get_stderr_message(stderr, name)) + + # UnicodeEncodeError errors: + self.assertIn('UnicodeEncodeError', + get_stderr_message(stderr, 'str % exception')) + self.assertIn('Traceback (most recent call last):', + get_stderr_message(stderr, 'str % exception')) + + def assert_stderr_python3(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_python2 if six.PY2 else assert_stderr_python3]] + + if six.PY2: + # In Python 2, only successfully formatted messages are logged. + 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] G\u00eete: Ch\u00e2tonnaye +'''.encode('utf-8') + else: + # In Python 3, all messages are formatted successfully and logged. + 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() diff --git a/absl/logging/tests/logging_functional_test_helper.py b/absl/logging/tests/logging_functional_test_helper.py new file mode 100755 index 0000000..017206d --- /dev/null +++ b/absl/logging/tests/logging_functional_test_helper.py @@ -0,0 +1,302 @@ +# 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. + +"""Helper script for logging_functional_test.""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import logging as std_logging +import os +import sys +import threading +import time + +from absl import app +from absl import flags +from absl import logging +from six.moves import xrange # pylint: disable=redefined-builtin + +FLAGS = flags.FLAGS + + +class VerboseDel(object): + """Dummy class to test __del__ running.""" + + def __init__(self, msg): + self._msg = msg + + def __del__(self): + sys.stderr.write(self._msg) + sys.stderr.flush() + + +def _test_do_logging(): + """Do some log operations.""" + logging.vlog(3, 'This line is VLOG level 3') + logging.vlog(2, 'This line is VLOG level 2') + logging.log(2, 'This line is log level 2') + + logging.vlog(1, 'This line is VLOG level 1') + logging.log(1, 'This line is log level 1') + logging.debug('This line is DEBUG') + + logging.vlog(0, 'This line is VLOG level 0') + logging.log(0, 'This line is log level 0') + logging.info('Interesting Stuff\0') + logging.info('Interesting Stuff with Arguments: %d', 42) + logging.info('%(a)s Stuff with %(b)s', + {'a': 'Interesting', 'b': 'Dictionary'}) + + for i in xrange(1, 5): + logging.log_first_n(logging.INFO, 'Info first %d of %d', 2, i, 2) + logging.log_every_n(logging.INFO, 'Info %d (every %d)', 3, i, 3) + + logging.vlog(-1, 'This line is VLOG level -1') + logging.log(-1, 'This line is log level -1') + logging.warn('Worrying Stuff') + for i in xrange(1, 5): + logging.log_first_n(logging.WARN, 'Warn first %d of %d', 2, i, 2) + logging.log_every_n(logging.WARN, 'Warn %d (every %d)', 3, i, 3) + + logging.vlog(-2, 'This line is VLOG level -2') + logging.log(-2, 'This line is log level -2') + try: + raise OSError('Fake Error') + except OSError: + saved_exc_info = sys.exc_info() + logging.exception('An Exception %s') + logging.exception('Once more, %(reason)s', {'reason': 'just because'}) + logging.error('Exception 2 %s', exc_info=True) + logging.error('Non-exception', exc_info=False) + + try: + sys.exc_clear() + except AttributeError: + # No sys.exc_clear() in Python 3, but this will clear sys.exc_info() too. + pass + + logging.error('Exception %s', '3', exc_info=saved_exc_info) + logging.error('No traceback', exc_info=saved_exc_info[:2] + (None,)) + + logging.error('Alarming Stuff') + for i in xrange(1, 5): + logging.log_first_n(logging.ERROR, 'Error first %d of %d', 2, i, 2) + logging.log_every_n(logging.ERROR, 'Error %d (every %d)', 3, i, 3) + logging.flush() + + +def _test_fatal_main_thread_only(): + """Test logging.fatal from main thread, no other threads running.""" + v = VerboseDel('fatal_main_thread_only main del called\n') + try: + logging.fatal('fatal_main_thread_only message') + finally: + del v + + +def _test_fatal_with_other_threads(): + """Test logging.fatal from main thread, other threads running.""" + + lock = threading.Lock() + lock.acquire() + + def sleep_forever(lock=lock): + v = VerboseDel('fatal_with_other_threads non-main del called\n') + try: + lock.release() + while True: + time.sleep(10000) + finally: + del v + + v = VerboseDel('fatal_with_other_threads main del called\n') + try: + # Start new thread + t = threading.Thread(target=sleep_forever) + t.start() + + # Wait for other thread + lock.acquire() + lock.release() + + # Die + logging.fatal('fatal_with_other_threads message') + while True: + time.sleep(10000) + finally: + del v + + +def _test_fatal_non_main_thread(): + """Test logging.fatal from non main thread.""" + + lock = threading.Lock() + lock.acquire() + + def die_soon(lock=lock): + v = VerboseDel('fatal_non_main_thread non-main del called\n') + try: + # Wait for signal from other thread + lock.acquire() + lock.release() + logging.fatal('fatal_non_main_thread message') + while True: + time.sleep(10000) + finally: + del v + + v = VerboseDel('fatal_non_main_thread main del called\n') + try: + # Start new thread + t = threading.Thread(target=die_soon) + t.start() + + # Signal other thread + lock.release() + + # Wait for it to die + while True: + time.sleep(10000) + finally: + del v + + +def _test_critical_from_non_absl_logger(): + """Test CRITICAL logs from non-absl loggers.""" + + std_logging.critical('A critical message') + + +def _test_register_frame_to_skip(): + """Test skipping frames for line number reporting.""" + + def _getline(): + + def _getline_inner(): + return logging.get_absl_logger().findCaller()[1] + + return _getline_inner() + + # Check register_frame_to_skip function to see if log frame skipping works. + line1 = _getline() + line2 = _getline() + logging.get_absl_logger().register_frame_to_skip(__file__, '_getline') + line3 = _getline() + # Both should be line number of the _getline_inner() call. + assert (line1 == line2), (line1, line2) + # line3 should be a line number in this function. + assert (line2 != line3), (line2, line3) + + +def _test_flush(): + """Test flush in various difficult cases.""" + # Flush, but one of the logfiles is closed + log_filename = os.path.join(FLAGS.log_dir, 'a_thread_with_logfile.txt') + with open(log_filename, 'w') as log_file: + logging.get_absl_handler().python_handler.stream = log_file + logging.flush() + + +def _test_stderrthreshold(): + """Tests modifying --stderrthreshold after flag parsing will work.""" + + def log_things(): + logging.debug('FLAGS.stderrthreshold=%s, debug log', FLAGS.stderrthreshold) + logging.info('FLAGS.stderrthreshold=%s, info log', FLAGS.stderrthreshold) + logging.warn('FLAGS.stderrthreshold=%s, warn log', FLAGS.stderrthreshold) + logging.error('FLAGS.stderrthreshold=%s, error log', FLAGS.stderrthreshold) + + FLAGS.stderrthreshold = 'debug' + log_things() + FLAGS.stderrthreshold = 'info' + log_things() + FLAGS.stderrthreshold = 'warn' + log_things() + FLAGS.stderrthreshold = 'error' + log_things() + + +def _test_std_logging(): + """Tests logs from std logging.""" + std_logging.debug('std debug log') + std_logging.info('std info log') + std_logging.warn('std warn log') + std_logging.error('std error log') + + +def _test_bad_exc_info(): + """Tests when a bad exc_info valud is provided.""" + logging.info('Bad exc_info', exc_info=(None, None)) + + +def _test_none_exc_info(): + """Tests when exc_info is requested but not available.""" + # Clear exc_info first. + try: + sys.exc_clear() + except AttributeError: + # No sys.exc_clear() in Python 3, but this will clear sys.exc_info() too. + pass + logging.info('None exc_info', exc_info=True) + + +def _test_unicode(): + """Tests unicode handling.""" + + test_names = [] + + def log(name, msg, *args): + """Logs the message, and ensures the same name is not logged again.""" + assert name not in test_names, ('test_unicode expects unique names to work,' + ' found existing name {}').format(name) + test_names.append(name) + + # Add line seprators so that tests can verify the output for each log + # message. + sys.stderr.write('-- begin {} --\n'.format(name)) + logging.info(msg, *args) + sys.stderr.write('-- end {} --\n'.format(name)) + + log('unicode', u'G\u00eete: Ch\u00e2tonnaye') + log('unicode % unicode', u'G\u00eete: %s', u'Ch\u00e2tonnaye') + log('bytes % bytes', u'G\u00eete: %s'.encode('utf-8'), + u'Ch\u00e2tonnaye'.encode('utf-8')) + log('unicode % bytes', u'G\u00eete: %s', u'Ch\u00e2tonnaye'.encode('utf-8')) + log('bytes % unicode', u'G\u00eete: %s'.encode('utf-8'), u'Ch\u00e2tonnaye') + log('unicode % iso8859-15', u'G\u00eete: %s', + u'Ch\u00e2tonnaye'.encode('iso-8859-15')) + log('str % exception', 'exception: %s', Exception(u'Ch\u00e2tonnaye')) + + +def main(argv): + del argv # Unused. + + test_name = os.environ.get('TEST_NAME', None) + test_fn = globals().get('_test_%s' % test_name) + if test_fn is None: + raise AssertionError('TEST_NAME must be set to a valid value') + # Flush so previous messages are written to file before we switch to a new + # file with use_absl_log_file. + logging.flush() + if os.environ.get('USE_ABSL_LOG_FILE') == '1': + logging.get_absl_handler().use_absl_log_file('absl_log_file', FLAGS.log_dir) + + test_fn() + + +if __name__ == '__main__': + sys.argv[0] = 'py_argv_0' + app.run(main) diff --git a/absl/logging/tests/logging_test.py b/absl/logging/tests/logging_test.py new file mode 100644 index 0000000..f6eddb4 --- /dev/null +++ b/absl/logging/tests/logging_test.py @@ -0,0 +1,734 @@ +# 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. + +"""Unit tests for absl.logging.""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import getpass +import io +import logging as std_logging +import os +import socket +import sys +import threading +import time +import traceback +import unittest + +from absl import flags +from absl import logging +from absl.testing import absltest +from absl.testing import flagsaver +from absl.testing import parameterized +import mock +import six +from six.moves import range # pylint: disable=redefined-builtin + + +FLAGS = flags.FLAGS + +_StreamIO = io.StringIO if six.PY3 else io.BytesIO # pylint: disable=invalid-name + + +class ConfigurationTest(absltest.TestCase): + """Tests the initial logging configuration.""" + + def test_logger_and_handler(self): + absl_logger = std_logging.getLogger('absl') + self.assertIs(absl_logger, logging.get_absl_logger()) + self.assertTrue(isinstance(absl_logger, logging.ABSLLogger)) + self.assertTrue( + isinstance(logging.get_absl_handler().python_handler.formatter, + logging.PythonFormatter)) + + +class PythonHandlerTest(absltest.TestCase): + """Tests the PythonHandler class.""" + + def setUp(self): + (year, month, day, hour, minute, sec, + dunno, dayofyear, dst_flag) = (1979, 10, 21, 18, 17, 16, 3, 15, 0) + self.now_tuple = (year, month, day, hour, minute, sec, + dunno, dayofyear, dst_flag) + self.python_handler = logging.PythonHandler() + + def tearDown(self): + mock.patch.stopall() + + @flagsaver.flagsaver(logtostderr=False) + def test_set_google_log_file_no_log_to_stderr(self): + with mock.patch.object(self.python_handler, 'start_logging_to_file'): + self.python_handler.use_absl_log_file() + self.python_handler.start_logging_to_file.assert_called_once_with( + program_name=None, log_dir=None) + + @flagsaver.flagsaver(logtostderr=True) + def test_set_google_log_file_with_log_to_stderr(self): + self.python_handler.stream = None + self.python_handler.use_absl_log_file() + self.assertEqual(sys.stderr, self.python_handler.stream) + + @mock.patch.object(logging, 'find_log_dir_and_names') + @mock.patch.object(logging.time, 'localtime') + @mock.patch.object(logging.time, 'time') + @mock.patch.object(os.path, 'islink') + @mock.patch.object(os, 'unlink') + @mock.patch.object(os, 'getpid') + def test_start_logging_to_file( + self, mock_getpid, mock_unlink, mock_islink, mock_time, + mock_localtime, mock_find_log_dir_and_names): + mock_find_log_dir_and_names.return_value = ('here', 'prog1', 'prog1') + mock_time.return_value = '12345' + mock_localtime.return_value = self.now_tuple + mock_getpid.return_value = 4321 + symlink = os.path.join('here', 'prog1.INFO') + mock_islink.return_value = True + with mock.patch.object( + logging, 'open', return_value=sys.stdout, create=True): + if getattr(os, 'symlink', None): + with mock.patch.object(os, 'symlink'): + self.python_handler.start_logging_to_file() + mock_unlink.assert_called_once_with(symlink) + os.symlink.assert_called_once_with( + 'prog1.INFO.19791021-181716.4321', symlink) + else: + self.python_handler.start_logging_to_file() + + def test_log_file(self): + handler = logging.PythonHandler() + self.assertEqual(sys.stderr, handler.stream) + + stream = mock.Mock() + handler = logging.PythonHandler(stream) + self.assertEqual(stream, handler.stream) + + def test_flush(self): + stream = mock.Mock() + handler = logging.PythonHandler(stream) + handler.flush() + stream.flush.assert_called_once() + + def test_flush_with_value_error(self): + stream = mock.Mock() + stream.flush.side_effect = ValueError + handler = logging.PythonHandler(stream) + handler.flush() + stream.flush.assert_called_once() + + def test_flush_with_environment_error(self): + stream = mock.Mock() + stream.flush.side_effect = EnvironmentError + handler = logging.PythonHandler(stream) + handler.flush() + stream.flush.assert_called_once() + + def test_flush_with_assertion_error(self): + stream = mock.Mock() + stream.flush.side_effect = AssertionError + handler = logging.PythonHandler(stream) + with self.assertRaises(AssertionError): + handler.flush() + + def test_log_to_std_err(self): + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + with mock.patch.object(std_logging.StreamHandler, 'emit'): + self.python_handler._log_to_stderr(record) + std_logging.StreamHandler.emit.assert_called_once_with(record) + + @flagsaver.flagsaver(logtostderr=True) + def test_emit_log_to_stderr(self): + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + with mock.patch.object(self.python_handler, '_log_to_stderr'): + self.python_handler.emit(record) + self.python_handler._log_to_stderr.assert_called_once_with(record) + + def test_emit(self): + stream = _StreamIO() + handler = logging.PythonHandler(stream) + handler.stderr_threshold = std_logging.FATAL + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + handler.emit(record) + self.assertEqual(1, stream.getvalue().count('logging_msg')) + + @flagsaver.flagsaver(stderrthreshold='debug') + def test_emit_and_stderr_threshold(self): + mock_stderr = _StreamIO() + stream = _StreamIO() + handler = logging.PythonHandler(stream) + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr: + handler.emit(record) + self.assertEqual(1, stream.getvalue().count('logging_msg')) + self.assertEqual(1, mock_stderr.getvalue().count('logging_msg')) + + @flagsaver.flagsaver(alsologtostderr=True) + def test_emit_also_log_to_stderr(self): + mock_stderr = _StreamIO() + stream = _StreamIO() + handler = logging.PythonHandler(stream) + handler.stderr_threshold = std_logging.FATAL + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr: + handler.emit(record) + self.assertEqual(1, stream.getvalue().count('logging_msg')) + self.assertEqual(1, mock_stderr.getvalue().count('logging_msg')) + + def test_emit_on_stderr(self): + mock_stderr = _StreamIO() + with mock.patch.object(sys, 'stderr', new=mock_stderr) as mock_stderr: + handler = logging.PythonHandler() + handler.stderr_threshold = std_logging.INFO + record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'logging_msg', [], False) + handler.emit(record) + self.assertEqual(1, mock_stderr.getvalue().count('logging_msg')) + + def test_emit_fatal_absl(self): + stream = _StreamIO() + handler = logging.PythonHandler(stream) + record = std_logging.LogRecord( + 'name', std_logging.FATAL, 'path', 12, 'logging_msg', [], False) + record.__dict__[logging._ABSL_LOG_FATAL] = True + with mock.patch.object(handler, 'flush') as mock_flush: + with mock.patch.object(os, 'abort') as mock_abort: + handler.emit(record) + mock_abort.assert_called_once() + mock_flush.assert_called() # flush is also called by super class. + + def test_emit_fatal_non_absl(self): + stream = _StreamIO() + handler = logging.PythonHandler(stream) + record = std_logging.LogRecord( + 'name', std_logging.FATAL, 'path', 12, 'logging_msg', [], False) + with mock.patch.object(os, 'abort') as mock_abort: + handler.emit(record) + mock_abort.assert_not_called() + + def test_close(self): + stream = mock.Mock() + stream.isatty.return_value = True + handler = logging.PythonHandler(stream) + with mock.patch.object(handler, 'flush') as mock_flush: + with mock.patch.object(std_logging.StreamHandler, 'close') as super_close: + handler.close() + mock_flush.assert_called_once() + super_close.assert_called_once() + stream.close.assert_not_called() + + def test_close_afile(self): + stream = mock.Mock() + stream.isatty.return_value = False + stream.close.side_effect = ValueError + handler = logging.PythonHandler(stream) + with mock.patch.object(handler, 'flush') as mock_flush: + with mock.patch.object(std_logging.StreamHandler, 'close') as super_close: + handler.close() + mock_flush.assert_called_once() + super_close.assert_called_once() + + def test_close_stderr(self): + with mock.patch.object(sys, 'stderr') as mock_stderr: + mock_stderr.isatty.return_value = False + handler = logging.PythonHandler(sys.stderr) + handler.close() + mock_stderr.close.assert_not_called() + + def test_close_stdout(self): + with mock.patch.object(sys, 'stdout') as mock_stdout: + mock_stdout.isatty.return_value = False + handler = logging.PythonHandler(sys.stdout) + handler.close() + mock_stdout.close.assert_not_called() + + def test_close_fake_file(self): + + class FakeFile(object): + """A file-like object that does not implement "isatty".""" + + def __init__(self): + self.closed = False + + def close(self): + self.closed = True + + def flush(self): + pass + + fake_file = FakeFile() + handler = logging.PythonHandler(fake_file) + handler.close() + self.assertTrue(fake_file.closed) + + +class PrefixFormatterTest(absltest.TestCase): + """Tests the PrefixFormatter class.""" + + def setUp(self): + self.now_tuple = time.localtime(time.mktime( + (1979, 10, 21, 18, 17, 16, 3, 15, 1))) + self.new_prefix = lambda level: '(blah_prefix)' + mock.patch.object(time, 'time').start() + mock.patch.object(time, 'localtime').start() + self.record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path', 12, 'A Message', [], False) + self.formatter = logging.PythonFormatter() + + def tearDown(self): + mock.patch.stopall() + + @mock.patch.object(logging._thread_lib, 'get_ident') + def test_get_thread_id(self, mock_get_ident): + mock_get_ident.return_value = 12345 + self.assertEqual(12345, logging._get_thread_id()) + + + +class ABSLHandlerTest(absltest.TestCase): + + def setUp(self): + formatter = logging.PythonFormatter() + self.absl_handler = logging.ABSLHandler(formatter) + + def test_activate_python_handler(self): + self.absl_handler.activate_python_handler() + self.assertEqual( + self.absl_handler._current_handler, self.absl_handler.python_handler) + + +class ABSLLoggerTest(absltest.TestCase): + """Tests the ABSLLogger class.""" + + def set_up_mock_frames(self): + """Sets up mock frames for use with the testFindCaller methods.""" + logging_file = os.path.join('absl', 'logging', '__init__.py') + + # Set up mock frame 0 + mock_frame_0 = mock.Mock() + mock_code_0 = mock.Mock() + mock_code_0.co_filename = logging_file + mock_code_0.co_name = 'LoggingLog' + mock_frame_0.f_code = mock_code_0 + mock_frame_0.f_lineno = 125 + + # Set up mock frame 1 + mock_frame_1 = mock.Mock() + mock_code_1 = mock.Mock() + mock_code_1.co_filename = 'myfile.py' + mock_code_1.co_name = 'Method1' + mock_frame_1.f_code = mock_code_1 + mock_frame_1.f_lineno = 125 + + # Set up mock frame 2 + mock_frame_2 = mock.Mock() + mock_code_2 = mock.Mock() + mock_code_2.co_filename = 'myfile.py' + mock_code_2.co_name = 'Method2' + mock_frame_2.f_code = mock_code_2 + mock_frame_2.f_lineno = 125 + + # Set up mock frame 3 + mock_frame_3 = mock.Mock() + mock_code_3 = mock.Mock() + mock_code_3.co_filename = 'myfile.py' + mock_code_3.co_name = 'Method3' + mock_frame_3.f_code = mock_code_3 + mock_frame_3.f_lineno = 125 + + # Tie them together. + mock_frame_3.f_back = None + mock_frame_2.f_back = mock_frame_3 + mock_frame_1.f_back = mock_frame_2 + mock_frame_0.f_back = mock_frame_1 + + mock.patch.object(std_logging, 'currentframe').start() + std_logging.currentframe.return_value = mock_frame_0 + + def setUp(self): + self.message = 'Hello Nurse' + self.logger = logging.ABSLLogger('') + + def tearDown(self): + mock.patch.stopall() + + def test_constructor_without_level(self): + self.logger = logging.ABSLLogger('') + self.assertEqual(std_logging.NOTSET, self.logger.getEffectiveLevel()) + + def test_constructor_with_level(self): + self.logger = logging.ABSLLogger('', std_logging.DEBUG) + self.assertEqual(std_logging.DEBUG, self.logger.getEffectiveLevel()) + + def test_find_caller_normal(self): + self.set_up_mock_frames() + expected_name = 'Method1' + self.assertEqual(expected_name, self.logger.findCaller()[2]) + + def test_find_caller_skip_method1(self): + self.set_up_mock_frames() + self.logger.register_frame_to_skip('myfile.py', 'Method1') + expected_name = 'Method2' + self.assertEqual(expected_name, self.logger.findCaller()[2]) + + def test_find_caller_skip_method1_and_method3(self): + self.set_up_mock_frames() + self.logger.register_frame_to_skip('myfile.py', 'Method1') + # Skiping Method3 should change nothing since Method2 should be hit. + self.logger.register_frame_to_skip('myfile.py', 'Method3') + expected_name = 'Method2' + self.assertEqual(expected_name, self.logger.findCaller()[2]) + + @unittest.skipIf(six.PY2, 'stack_info is only supported in Python 3.') + def test_find_caller_stack_info(self): + self.set_up_mock_frames() + with mock.patch.object(traceback, 'print_stack') as print_stack: + self.assertEqual( + ('myfile.py', 125, 'Method2', 'Stack (most recent call last):'), + self.logger.findCaller(stack_info=True)) + print_stack.assert_called_once() + + def test_critical(self): + with mock.patch.object(self.logger, 'log'): + self.logger.critical(self.message) + self.logger.log.assert_called_once_with( + std_logging.CRITICAL, self.message) + + def test_fatal(self): + with mock.patch.object(self.logger, 'log'): + self.logger.fatal(self.message) + self.logger.log.assert_called_once_with(std_logging.FATAL, self.message) + + def test_error(self): + with mock.patch.object(self.logger, 'log'): + self.logger.error(self.message) + self.logger.log.assert_called_once_with(std_logging.ERROR, self.message) + + def test_warn(self): + with mock.patch.object(self.logger, 'log'): + self.logger.warn(self.message) + self.logger.log.assert_called_once_with(std_logging.WARN, self.message) + + def test_warning(self): + with mock.patch.object(self.logger, 'log'): + self.logger.warning(self.message) + self.logger.log.assert_called_once_with(std_logging.WARNING, self.message) + + def test_info(self): + with mock.patch.object(self.logger, 'log'): + self.logger.info(self.message) + self.logger.log.assert_called_once_with(std_logging.INFO, self.message) + + def test_debug(self): + with mock.patch.object(self.logger, 'log'): + self.logger.debug(self.message) + self.logger.log.assert_called_once_with(std_logging.DEBUG, self.message) + + def test_log_debug_with_python(self): + with mock.patch.object(self.logger, 'log'): + FLAGS.verbosity = 1 + self.logger.debug(self.message) + self.logger.log.assert_called_once_with(std_logging.DEBUG, self.message) + + def test_log_fatal_with_python(self): + with mock.patch.object(self.logger, 'log'): + self.logger.fatal(self.message) + self.logger.log.assert_called_once_with(std_logging.FATAL, self.message) + + def test_register_frame_to_skip(self): + # This is basically just making sure that if I put something in a + # list, it actually appears in that list. + frame_tuple = ('file', 'method') + self.logger.register_frame_to_skip(frame_tuple[0], frame_tuple[1]) + self.assertIn(frame_tuple, self.logger._frames_to_skip) + + def test_logger_cannot_be_disabled(self): + self.logger.disabled = True + record = self.logger.makeRecord( + 'name', std_logging.INFO, 'fn', 20, 'msg', [], False) + with mock.patch.object(self.logger, 'callHandlers') as mock_call_handlers: + self.logger.handle(record) + mock_call_handlers.assert_called_once() + + +class ABSLLogPrefixTest(parameterized.TestCase): + + def setUp(self): + self.record = std_logging.LogRecord( + 'name', std_logging.INFO, 'path/to/source.py', 13, 'log message', + None, None) + + @parameterized.named_parameters( + ('debug', std_logging.DEBUG, 'I'), + ('info', std_logging.INFO, 'I'), + ('warning', std_logging.WARNING, 'W'), + ('error', std_logging.ERROR, 'E'), + ) + def test_default_prefixes(self, levelno, level_prefix): + self.record.levelno = levelno + self.record.created = 1494293880.378885 + thread_id = '{: >5}'.format(logging._get_thread_id()) + # Use UTC so the test passes regardless of the local time zone. + with mock.patch.object(time, 'localtime', side_effect=time.gmtime): + self.assertEqual( + '{}0509 01:38:00.378885 {} source.py:13] '.format( + level_prefix, thread_id), + logging.get_absl_log_prefix(self.record)) + time.localtime.assert_called_once_with(self.record.created) + + def test_critical_absl(self): + self.record.levelno = std_logging.CRITICAL + self.record.created = 1494293880.378885 + self.record._absl_log_fatal = True + thread_id = '{: >5}'.format(logging._get_thread_id()) + # Use UTC so the test passes regardless of the local time zone. + with mock.patch.object(time, 'localtime', side_effect=time.gmtime): + self.assertEqual( + 'F0509 01:38:00.378885 {} source.py:13] '.format(thread_id), + logging.get_absl_log_prefix(self.record)) + time.localtime.assert_called_once_with(self.record.created) + + def test_critical_non_absl(self): + self.record.levelno = std_logging.CRITICAL + self.record.created = 1494293880.378885 + thread_id = '{: >5}'.format(logging._get_thread_id()) + # Use UTC so the test passes regardless of the local time zone. + with mock.patch.object(time, 'localtime', side_effect=time.gmtime): + self.assertEqual( + 'E0509 01:38:00.378885 {} source.py:13] CRITICAL - '.format( + thread_id), + logging.get_absl_log_prefix(self.record)) + time.localtime.assert_called_once_with(self.record.created) + + +class LogCountTest(absltest.TestCase): + + def test_counter_threadsafe(self): + threads_start = threading.Event() + counts = set() + k = object() + + def t(): + threads_start.wait() + counts.add(logging._get_next_log_count_per_token(k)) + + threads = [threading.Thread(target=t) for _ in range(100)] + for thread in threads: + thread.start() + threads_start.set() + for thread in threads: + thread.join() + self.assertEqual(counts, {i for i in range(100)}) + + +class LoggingTest(absltest.TestCase): + + def test_fatal(self): + with mock.patch.object(os, 'abort') as mock_abort: + logging.fatal('Die!') + mock_abort.assert_called_once() + + def test_find_log_dir_with_arg(self): + with mock.patch.object(os, 'access'), \ + mock.patch.object(os.path, 'isdir'): + os.path.isdir.return_value = True + os.access.return_value = True + log_dir = logging.find_log_dir(log_dir='./') + self.assertEqual('./', log_dir) + + @flagsaver.flagsaver(log_dir='./') + def test_find_log_dir_with_flag(self): + with mock.patch.object(os, 'access'), \ + mock.patch.object(os.path, 'isdir'): + os.path.isdir.return_value = True + os.access.return_value = True + log_dir = logging.find_log_dir() + self.assertEqual('./', log_dir) + + @flagsaver.flagsaver(log_dir='') + def test_find_log_dir_with_hda_tmp(self): + with mock.patch.object(os, 'access'), \ + mock.patch.object(os.path, 'exists'), \ + mock.patch.object(os.path, 'isdir'): + os.path.exists.return_value = True + os.path.isdir.return_value = True + os.access.return_value = True + log_dir = logging.find_log_dir() + self.assertEqual('/tmp/', log_dir) + + @flagsaver.flagsaver(log_dir='') + def test_find_log_dir_with_tmp(self): + with mock.patch.object(os, 'access'), \ + mock.patch.object(os.path, 'exists'), \ + mock.patch.object(os.path, 'isdir'): + os.path.exists.return_value = False + os.path.isdir.side_effect = lambda path: path == '/tmp/' + os.access.return_value = True + log_dir = logging.find_log_dir() + self.assertEqual('/tmp/', log_dir) + + def test_find_log_dir_with_nothing(self): + with mock.patch.object(os.path, 'exists'), \ + mock.patch.object(os.path, 'isdir'), \ + mock.patch.object(logging.get_absl_logger(), 'fatal') as mock_fatal: + os.path.exists.return_value = False + os.path.isdir.return_value = False + log_dir = logging.find_log_dir() + mock_fatal.assert_called() + self.assertEqual(None, log_dir) + + def test_find_log_dir_and_names_with_args(self): + user = 'test_user' + host = 'test_host' + log_dir = 'here' + program_name = 'prog1' + with mock.patch.object(getpass, 'getuser'), \ + mock.patch.object(logging, 'find_log_dir') as mock_find_log_dir, \ + mock.patch.object(socket, 'gethostname') as mock_gethostname: + getpass.getuser.return_value = user + mock_gethostname.return_value = host + mock_find_log_dir.return_value = log_dir + + prefix = '%s.%s.%s.log' % (program_name, host, user) + self.assertEqual((log_dir, prefix, program_name), + logging.find_log_dir_and_names( + program_name=program_name, log_dir=log_dir)) + + def test_find_log_dir_and_names_without_args(self): + user = 'test_user' + host = 'test_host' + log_dir = 'here' + py_program_name = 'py_prog1' + sys.argv[0] = 'path/to/prog1' + with mock.patch.object(getpass, 'getuser'), \ + mock.patch.object(logging, 'find_log_dir') as mock_find_log_dir, \ + mock.patch.object(socket, 'gethostname'): + getpass.getuser.return_value = user + socket.gethostname.return_value = host + mock_find_log_dir.return_value = log_dir + prefix = '%s.%s.%s.log' % (py_program_name, host, user) + self.assertEqual((log_dir, prefix, py_program_name), + logging.find_log_dir_and_names()) + + def test_errors_in_logging(self): + with mock.patch.object(sys, 'stderr', new=_StreamIO()) as stderr: + logging.info('not enough args: %s %s', 'foo') # pylint: disable=logging-too-few-args + self.assertIn('Traceback (most recent call last):', stderr.getvalue()) + self.assertIn('TypeError', stderr.getvalue()) + + def test_dict_arg(self): + # Tests that passing a dictionary as a single argument does not crash. + logging.info('%(test)s', {'test': 'Hello world!'}) + + def test_exception_dict_format(self): + # Just verify that this doesn't raise a TypeError. + logging.exception('%(test)s', {'test': 'Hello world!'}) + + def test_logging_levels(self): + old_level = logging.get_verbosity() + + logging.set_verbosity(logging.DEBUG) + self.assert_(logging.get_verbosity() == logging.DEBUG) + self.assert_(logging.level_debug()) + self.assert_(logging.level_info()) + self.assert_(logging.level_warn()) + self.assert_(logging.level_error()) + + logging.set_verbosity(logging.INFO) + self.assert_(logging.get_verbosity() == logging.INFO) + self.assert_(not logging.level_debug()) + self.assert_(logging.level_info()) + self.assert_(logging.level_warn()) + self.assert_(logging.level_error()) + + logging.set_verbosity(logging.WARN) + self.assert_(logging.get_verbosity() == logging.WARN) + self.assert_(not logging.level_debug()) + self.assert_(not logging.level_info()) + self.assert_(logging.level_warn()) + self.assert_(logging.level_error()) + + logging.set_verbosity(logging.ERROR) + self.assert_(logging.get_verbosity() == logging.ERROR) + self.assert_(not logging.level_debug()) + self.assert_(not logging.level_info()) + self.assert_(not logging.level_warn()) + self.assert_(logging.level_error()) + + logging.set_verbosity(old_level) + + def test_set_verbosity_strings(self): + old_level = logging.get_verbosity() + + # Lowercase names. + logging.set_verbosity('debug') + self.assert_(logging.get_verbosity() == logging.DEBUG) + logging.set_verbosity('info') + self.assert_(logging.get_verbosity() == logging.INFO) + logging.set_verbosity('warn') + self.assert_(logging.get_verbosity() == logging.WARN) + logging.set_verbosity('error') + self.assert_(logging.get_verbosity() == logging.ERROR) + logging.set_verbosity('fatal') + + # Uppercase names. + self.assert_(logging.get_verbosity() == logging.FATAL) + logging.set_verbosity('DEBUG') + self.assert_(logging.get_verbosity() == logging.DEBUG) + logging.set_verbosity('INFO') + self.assert_(logging.get_verbosity() == logging.INFO) + logging.set_verbosity('WARN') + self.assert_(logging.get_verbosity() == logging.WARN) + logging.set_verbosity('ERROR') + self.assert_(logging.get_verbosity() == logging.ERROR) + logging.set_verbosity('FATAL') + self.assert_(logging.get_verbosity() == logging.FATAL) + + # Integers as strings. + logging.set_verbosity(str(logging.DEBUG)) + self.assert_(logging.get_verbosity() == logging.DEBUG) + logging.set_verbosity(str(logging.INFO)) + self.assert_(logging.get_verbosity() == logging.INFO) + logging.set_verbosity(str(logging.WARN)) + self.assert_(logging.get_verbosity() == logging.WARN) + logging.set_verbosity(str(logging.ERROR)) + self.assert_(logging.get_verbosity() == logging.ERROR) + logging.set_verbosity(str(logging.FATAL)) + self.assert_(logging.get_verbosity() == logging.FATAL) + + logging.set_verbosity(old_level) + + def test_key_flags(self): + key_flags = FLAGS.get_key_flags_for_module(logging) + key_flag_names = [flag.name for flag in key_flags] + self.assertIn('stderrthreshold', key_flag_names) + self.assertIn('verbosity', key_flag_names) + + def test_get_absl_logger(self): + self.assertIsInstance( + logging.get_absl_logger(), logging.ABSLLogger) + + def test_get_absl_handler(self): + self.assertIsInstance( + logging.get_absl_handler(), logging.ABSLHandler) + + +if __name__ == '__main__': + absltest.main() diff --git a/absl/logging/tests/verbosity_flag_test.py b/absl/logging/tests/verbosity_flag_test.py new file mode 100644 index 0000000..66436d2 --- /dev/null +++ b/absl/logging/tests/verbosity_flag_test.py @@ -0,0 +1,58 @@ +# 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. + +"""Tests -v/--verbosity flag and logging.root level's sync behavior.""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function + +import logging + +assert logging.root.getEffectiveLevel() == logging.WARN, ( + 'default logging.root level should be WARN, but found {}'.format( + logging.root.getEffectiveLevel())) + +# This is here to test importing logging won't change the level. +logging.root.setLevel(logging.ERROR) + +assert logging.root.getEffectiveLevel() == logging.ERROR, ( + 'logging.root level should be changed to ERROR, but found {}'.format( + logging.root.getEffectiveLevel())) + + +from absl import flags +from absl import logging as _ # pylint: disable=unused-import +from absl.testing import absltest + + +FLAGS = flags.FLAGS + +assert FLAGS['verbosity'].value == -1, ( + '-v/--verbosity should be -1 before flags are parsed.') + +assert logging.root.getEffectiveLevel() == logging.ERROR, ( + 'logging.root level should be kept to ERROR, but found {}'.format( + logging.root.getEffectiveLevel())) + + +class VerbosityFlagTest(absltest.TestCase): + + def test_default_value_after_init(self): + self.assertEqual(0, FLAGS.verbosity) + self.assertEqual(logging.INFO, logging.root.getEffectiveLevel()) + + +if __name__ == '__main__': + absltest.main() |