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