1# -*- coding: utf-8 -*- 2 3# Copyright (c) 2011 United States Government as represented by the 4# Administrator of the National Aeronautics and Space Administration. 5# All Rights Reserved. 6 7# Licensed under the Apache License, Version 2.0 (the "License"); you may 8# not use this file except in compliance with the License. You may obtain 9# a copy of the License at 10# 11# http://www.apache.org/licenses/LICENSE-2.0 12# 13# Unless required by applicable law or agreed to in writing, software 14# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT 15# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the 16# License for the specific language governing permissions and limitations 17# under the License. 18 19from contextlib import contextmanager 20import copy 21import datetime 22import io 23import logging 24import os 25import platform 26import shutil 27import sys 28try: 29 import syslog 30except ImportError: 31 syslog = None 32try: 33 from systemd import journal 34except ImportError: 35 journal = None 36import tempfile 37import time 38from unittest import mock 39 40from dateutil import tz 41from oslo_config import cfg 42from oslo_config import fixture as fixture_config # noqa 43from oslo_context import context 44from oslo_context import fixture as fixture_context 45from oslo_i18n import fixture as fixture_trans 46from oslo_serialization import jsonutils 47from oslotest import base as test_base 48import testtools 49 50from oslo_log import _options 51from oslo_log import formatters 52from oslo_log import handlers 53from oslo_log import log 54from oslo_utils import units 55 56 57MIN_LOG_INI = b"""[loggers] 58keys=root 59 60[formatters] 61keys= 62 63[handlers] 64keys= 65 66[logger_root] 67handlers= 68""" 69 70 71def _fake_context(): 72 ctxt = context.RequestContext(1, 1, overwrite=True) 73 ctxt.user = 'myuser' 74 ctxt.tenant = 'mytenant' 75 ctxt.domain = 'mydomain' 76 ctxt.project_domain = 'myprojectdomain' 77 ctxt.user_domain = 'myuserdomain' 78 79 return ctxt 80 81 82def _fake_new_context(): 83 # New style contexts have a user_name / project_name, this is done 84 # distinctly from the above context to not have to rewrite all the 85 # other tests. 86 ctxt = context.RequestContext(1, 1, overwrite=True) 87 ctxt.user_name = 'myuser' 88 ctxt.project_name = 'mytenant' 89 ctxt.domain = 'mydomain' 90 ctxt.project_domain = 'myprojectdomain' 91 ctxt.user_domain = 'myuserdomain' 92 93 return ctxt 94 95 96class CommonLoggerTestsMixIn(object): 97 """These tests are shared between LoggerTestCase and 98 LazyLoggerTestCase. 99 """ 100 101 def setUp(self): 102 super(CommonLoggerTestsMixIn, self).setUp() 103 # common context has different fields to the defaults in log.py 104 self.config_fixture = self.useFixture( 105 fixture_config.Config(cfg.ConfigOpts())) 106 self.config = self.config_fixture.config 107 self.CONF = self.config_fixture.conf 108 log.register_options(self.config_fixture.conf) 109 self.config(logging_context_format_string='%(asctime)s %(levelname)s ' 110 '%(name)s [%(request_id)s ' 111 '%(user)s %(tenant)s] ' 112 '%(message)s') 113 self.log = None 114 log._setup_logging_from_conf(self.config_fixture.conf, 'test', 'test') 115 self.log_handlers = log.getLogger(None).logger.handlers 116 117 def test_handlers_have_context_formatter(self): 118 formatters_list = [] 119 for h in self.log.logger.handlers: 120 f = h.formatter 121 if isinstance(f, formatters.ContextFormatter): 122 formatters_list.append(f) 123 self.assertTrue(formatters_list) 124 self.assertEqual(len(formatters_list), len(self.log.logger.handlers)) 125 126 def test_handles_context_kwarg(self): 127 self.log.info("foo", context=_fake_context()) 128 self.assertTrue(True) # didn't raise exception 129 130 def test_will_be_debug_if_debug_flag_set(self): 131 self.config(debug=True) 132 logger_name = 'test_is_debug' 133 log.setup(self.CONF, logger_name) 134 logger = logging.getLogger(logger_name) 135 self.assertEqual(logging.DEBUG, logger.getEffectiveLevel()) 136 137 def test_will_be_info_if_debug_flag_not_set(self): 138 self.config(debug=False) 139 logger_name = 'test_is_not_debug' 140 log.setup(self.CONF, logger_name) 141 logger = logging.getLogger(logger_name) 142 self.assertEqual(logging.INFO, logger.getEffectiveLevel()) 143 144 def test_no_logging_via_module(self): 145 for func in ('critical', 'error', 'exception', 'warning', 'warn', 146 'info', 'debug', 'log'): 147 self.assertRaises(AttributeError, getattr, log, func) 148 149 @mock.patch('platform.system', return_value='Linux') 150 def test_eventlog_missing(self, platform_mock): 151 self.config(use_eventlog=True) 152 self.assertRaises(RuntimeError, 153 log._setup_logging_from_conf, 154 self.CONF, 155 'test', 156 'test') 157 158 @mock.patch('platform.system', return_value='Windows') 159 @mock.patch('logging.handlers.NTEventLogHandler') 160 @mock.patch('oslo_log.log.getLogger') 161 def test_eventlog(self, loggers_mock, handler_mock, platform_mock): 162 self.config(use_eventlog=True) 163 log._setup_logging_from_conf(self.CONF, 'test', 'test') 164 handler_mock.assert_called_once_with('test') 165 mock_logger = loggers_mock.return_value.logger 166 mock_logger.addHandler.assert_any_call(handler_mock.return_value) 167 168 @mock.patch('oslo_log.watchers.FastWatchedFileHandler') 169 @mock.patch('oslo_log.log._get_log_file_path', return_value='test.conf') 170 @mock.patch('platform.system', return_value='Linux') 171 def test_watchlog_on_linux(self, platfotm_mock, path_mock, handler_mock): 172 self.config(watch_log_file=True) 173 log._setup_logging_from_conf(self.CONF, 'test', 'test') 174 handler_mock.assert_called_once_with(path_mock.return_value) 175 self.assertEqual(self.log_handlers[0], handler_mock.return_value) 176 177 @mock.patch('logging.handlers.WatchedFileHandler') 178 @mock.patch('oslo_log.log._get_log_file_path', return_value='test.conf') 179 @mock.patch('platform.system', return_value='Windows') 180 def test_watchlog_on_windows(self, platform_mock, path_mock, handler_mock): 181 self.config(watch_log_file=True) 182 log._setup_logging_from_conf(self.CONF, 'test', 'test') 183 handler_mock.assert_called_once_with(path_mock.return_value) 184 self.assertEqual(self.log_handlers[0], handler_mock.return_value) 185 186 @mock.patch('logging.handlers.TimedRotatingFileHandler') 187 @mock.patch('oslo_log.log._get_log_file_path', return_value='test.conf') 188 def test_timed_rotate_log(self, path_mock, handler_mock): 189 rotation_type = 'interval' 190 when = 'weekday' 191 interval = 2 192 backup_count = 2 193 self.config(log_rotation_type=rotation_type, 194 log_rotate_interval=interval, 195 log_rotate_interval_type=when, 196 max_logfile_count=backup_count) 197 log._setup_logging_from_conf(self.CONF, 'test', 'test') 198 handler_mock.assert_called_once_with(path_mock.return_value, 199 when='w2', 200 interval=interval, 201 backupCount=backup_count) 202 self.assertEqual(self.log_handlers[0], handler_mock.return_value) 203 204 @mock.patch('logging.handlers.RotatingFileHandler') 205 @mock.patch('oslo_log.log._get_log_file_path', return_value='test.conf') 206 def test_rotate_log(self, path_mock, handler_mock): 207 rotation_type = 'size' 208 max_logfile_size_mb = 100 209 maxBytes = max_logfile_size_mb * units.Mi 210 backup_count = 2 211 self.config(log_rotation_type=rotation_type, 212 max_logfile_size_mb=max_logfile_size_mb, 213 max_logfile_count=backup_count) 214 log._setup_logging_from_conf(self.CONF, 'test', 'test') 215 handler_mock.assert_called_once_with(path_mock.return_value, 216 maxBytes=maxBytes, 217 backupCount=backup_count) 218 self.assertEqual(self.log_handlers[0], handler_mock.return_value) 219 220 221class LoggerTestCase(CommonLoggerTestsMixIn, test_base.BaseTestCase): 222 def setUp(self): 223 super(LoggerTestCase, self).setUp() 224 self.log = log.getLogger(None) 225 226 227class BaseTestCase(test_base.BaseTestCase): 228 def setUp(self): 229 super(BaseTestCase, self).setUp() 230 self.context_fixture = self.useFixture( 231 fixture_context.ClearRequestContext()) 232 self.config_fixture = self.useFixture( 233 fixture_config.Config(cfg.ConfigOpts())) 234 self.config = self.config_fixture.config 235 self.CONF = self.config_fixture.conf 236 log.register_options(self.CONF) 237 log.setup(self.CONF, 'base') 238 239 240class LogTestBase(BaseTestCase): 241 """Base test class that provides some convenience functions.""" 242 def _add_handler_with_cleanup(self, log_instance, handler=None, 243 formatter=None): 244 """Add a log handler to a log instance. 245 246 This function should be used to add handlers to loggers in test cases 247 instead of directly adding them to ensure that the handler is 248 correctly removed at the end of the test. Otherwise the handler may 249 be left on the logger and interfere with subsequent tests. 250 251 :param log_instance: The log instance to which the handler will be 252 added. 253 :param handler: The handler class to be added. Must be the class 254 itself, not an instance. 255 :param formatter: The formatter class to set on the handler. Must be 256 the class itself, not an instance. 257 """ 258 self.stream = io.StringIO() 259 if handler is None: 260 handler = logging.StreamHandler 261 self.handler = handler(self.stream) 262 if formatter is None: 263 formatter = formatters.ContextFormatter 264 self.handler.setFormatter(formatter()) 265 log_instance.logger.addHandler(self.handler) 266 self.addCleanup(log_instance.logger.removeHandler, self.handler) 267 268 def _set_log_level_with_cleanup(self, log_instance, level): 269 """Set the log level of a logger for the duration of a test. 270 271 Use this function to set the log level of a logger and add the 272 necessary cleanup to reset it back to default at the end of the test. 273 274 :param log_instance: The logger whose level will be changed. 275 :param level: The new log level to use. 276 """ 277 self.level = log_instance.logger.getEffectiveLevel() 278 log_instance.logger.setLevel(level) 279 self.addCleanup(log_instance.logger.setLevel, self.level) 280 281 282class LogHandlerTestCase(BaseTestCase): 283 def test_log_path_logdir(self): 284 path = os.path.join('some', 'path') 285 binary = 'foo-bar' 286 expected = os.path.join(path, '%s.log' % binary) 287 self.config(log_dir=path, log_file=None) 288 self.assertEqual(log._get_log_file_path(self.config_fixture.conf, 289 binary=binary), 290 expected) 291 292 def test_log_path_logfile(self): 293 path = os.path.join('some', 'path') 294 binary = 'foo-bar' 295 expected = os.path.join(path, '%s.log' % binary) 296 self.config(log_file=expected) 297 self.assertEqual(log._get_log_file_path(self.config_fixture.conf, 298 binary=binary), 299 expected) 300 301 def test_log_path_none(self): 302 prefix = 'foo-bar' 303 self.config(log_dir=None, log_file=None) 304 self.assertIsNone(log._get_log_file_path(self.config_fixture.conf, 305 binary=prefix)) 306 307 def test_log_path_logfile_overrides_logdir(self): 308 path = os.path.join(os.sep, 'some', 'path') 309 prefix = 'foo-bar' 310 expected = os.path.join(path, '%s.log' % prefix) 311 self.config(log_dir=os.path.join('some', 'other', 'path'), 312 log_file=expected) 313 self.assertEqual(log._get_log_file_path(self.config_fixture.conf, 314 binary=prefix), 315 expected) 316 317 def test_iter_loggers(self): 318 mylog = logging.getLogger("abc.cde") 319 loggers = list(log._iter_loggers()) 320 self.assertIn(logging.getLogger(), loggers) 321 self.assertIn(mylog, loggers) 322 323 324class SysLogHandlersTestCase(BaseTestCase): 325 """Test the standard Syslog handler.""" 326 def setUp(self): 327 super(SysLogHandlersTestCase, self).setUp() 328 self.facility = logging.handlers.SysLogHandler.LOG_USER 329 self.logger = logging.handlers.SysLogHandler(facility=self.facility) 330 331 def test_standard_format(self): 332 """Ensure syslog msg isn't modified for standard handler.""" 333 logrecord = logging.LogRecord('name', logging.WARNING, '/tmp', 1, 334 'Message', None, None) 335 expected = logrecord 336 self.assertEqual(expected.getMessage(), 337 self.logger.format(logrecord)) 338 339 340@testtools.skipUnless(syslog, "syslog is not available") 341class OSSysLogHandlerTestCase(BaseTestCase): 342 def test_handler(self): 343 handler = handlers.OSSysLogHandler() 344 syslog.syslog = mock.Mock() 345 handler.emit( 346 logging.LogRecord("foo", logging.INFO, 347 "path", 123, "hey!", 348 None, None)) 349 self.assertTrue(syslog.syslog.called) 350 351 def test_syslog_binary_name(self): 352 # There is no way to test the actual output written to the 353 # syslog (e.g. /var/log/syslog) to confirm binary_name value 354 # is actually present 355 syslog.openlog = mock.Mock() 356 handlers.OSSysLogHandler() 357 syslog.openlog.assert_called_with(handlers._get_binary_name(), 358 0, syslog.LOG_USER) 359 360 def test_find_facility(self): 361 self.assertEqual(syslog.LOG_USER, log._find_facility("user")) 362 self.assertEqual(syslog.LOG_LPR, log._find_facility("LPR")) 363 self.assertEqual(syslog.LOG_LOCAL3, log._find_facility("log_local3")) 364 self.assertEqual(syslog.LOG_UUCP, log._find_facility("LOG_UUCP")) 365 self.assertRaises(TypeError, 366 log._find_facility, 367 "fougere") 368 369 def test_syslog(self): 370 msg_unicode = u"Benoît Knecht & François Deppierraz login failure" 371 handler = handlers.OSSysLogHandler() 372 syslog.syslog = mock.Mock() 373 handler.emit( 374 logging.LogRecord("name", logging.INFO, "path", 123, 375 msg_unicode, None, None)) 376 syslog.syslog.assert_called_once_with(syslog.LOG_INFO, msg_unicode) 377 378 379class OSJournalHandlerTestCase(BaseTestCase): 380 """Test systemd journal logging. 381 382 This is a lightweight test for testing systemd journal logging. It 383 mocks out the journal interface itself, which allows us to not 384 have to have systemd-python installed (which is not possible to 385 install on non Linux environments). 386 387 Real world testing is also encouraged. 388 389 """ 390 def setUp(self): 391 super(OSJournalHandlerTestCase, self).setUp() 392 self.config(use_journal=True) 393 self.journal = mock.patch("oslo_log.handlers.journal").start() 394 self.addCleanup(self.journal.stop) 395 log.setup(self.CONF, 'testing') 396 397 @testtools.skipUnless(journal, "systemd journal binding is not available") 398 def test_handler(self): 399 handler = handlers.OSJournalHandler() 400 handler.emit( 401 logging.LogRecord("foo", logging.INFO, 402 "path", 123, "hey!", 403 None, None)) 404 self.assertTrue(self.journal.send.called) 405 406 def test_emit(self): 407 logger = log.getLogger('nova-test.foo') 408 local_context = _fake_new_context() 409 logger.info("Foo", context=local_context) 410 self.assertEqual( 411 mock.call(mock.ANY, CODE_FILE=mock.ANY, CODE_FUNC='test_emit', 412 CODE_LINE=mock.ANY, LOGGER_LEVEL='INFO', 413 LOGGER_NAME='nova-test.foo', PRIORITY=6, 414 SYSLOG_FACILITY=syslog.LOG_USER, 415 SYSLOG_IDENTIFIER=mock.ANY, 416 REQUEST_ID=mock.ANY, 417 PROJECT_NAME='mytenant', 418 PROCESS_NAME='MainProcess', 419 THREAD_NAME='MainThread', 420 USER_NAME='myuser'), 421 self.journal.send.call_args) 422 args, kwargs = self.journal.send.call_args 423 self.assertEqual(len(args), 1) 424 self.assertIsInstance(args[0], str) 425 self.assertIsInstance(kwargs['CODE_LINE'], int) 426 self.assertIsInstance(kwargs['PRIORITY'], int) 427 self.assertIsInstance(kwargs['SYSLOG_FACILITY'], int) 428 del kwargs['CODE_LINE'], kwargs['PRIORITY'], kwargs['SYSLOG_FACILITY'] 429 for key, arg in kwargs.items(): 430 self.assertIsInstance(key, str) 431 self.assertIsInstance(arg, (bytes, str)) 432 433 def test_emit_exception(self): 434 logger = log.getLogger('nova-exception.foo') 435 local_context = _fake_new_context() 436 try: 437 raise Exception("Some exception") 438 except Exception: 439 logger.exception("Foo", context=local_context) 440 self.assertEqual( 441 mock.call(mock.ANY, CODE_FILE=mock.ANY, 442 CODE_FUNC='test_emit_exception', 443 CODE_LINE=mock.ANY, LOGGER_LEVEL='ERROR', 444 LOGGER_NAME='nova-exception.foo', PRIORITY=3, 445 SYSLOG_FACILITY=syslog.LOG_USER, 446 SYSLOG_IDENTIFIER=mock.ANY, 447 REQUEST_ID=mock.ANY, 448 EXCEPTION_INFO=mock.ANY, 449 EXCEPTION_TEXT=mock.ANY, 450 PROJECT_NAME='mytenant', 451 PROCESS_NAME='MainProcess', 452 THREAD_NAME='MainThread', 453 USER_NAME='myuser'), 454 self.journal.send.call_args) 455 args, kwargs = self.journal.send.call_args 456 self.assertEqual(len(args), 1) 457 self.assertIsInstance(args[0], str) 458 self.assertIsInstance(kwargs['CODE_LINE'], int) 459 self.assertIsInstance(kwargs['PRIORITY'], int) 460 self.assertIsInstance(kwargs['SYSLOG_FACILITY'], int) 461 del kwargs['CODE_LINE'], kwargs['PRIORITY'], kwargs['SYSLOG_FACILITY'] 462 for key, arg in kwargs.items(): 463 self.assertIsInstance(key, str) 464 self.assertIsInstance(arg, (bytes, str)) 465 466 467class LogLevelTestCase(BaseTestCase): 468 def setUp(self): 469 super(LogLevelTestCase, self).setUp() 470 levels = self.CONF.default_log_levels 471 info_level = 'nova-test' 472 warn_level = 'nova-not-debug' 473 other_level = 'nova-below-debug' 474 trace_level = 'nova-trace' 475 levels.append(info_level + '=INFO') 476 levels.append(warn_level + '=WARN') 477 levels.append(other_level + '=7') 478 levels.append(trace_level + '=TRACE') 479 self.config(default_log_levels=levels) 480 log.setup(self.CONF, 'testing') 481 self.log = log.getLogger(info_level) 482 self.log_no_debug = log.getLogger(warn_level) 483 self.log_below_debug = log.getLogger(other_level) 484 self.log_trace = log.getLogger(trace_level) 485 486 def test_is_enabled_for(self): 487 self.assertTrue(self.log.isEnabledFor(logging.INFO)) 488 self.assertFalse(self.log_no_debug.isEnabledFor(logging.DEBUG)) 489 self.assertTrue(self.log_below_debug.isEnabledFor(logging.DEBUG)) 490 self.assertTrue(self.log_below_debug.isEnabledFor(7)) 491 self.assertTrue(self.log_trace.isEnabledFor(log.TRACE)) 492 493 def test_has_level_from_flags(self): 494 self.assertEqual(logging.INFO, self.log.logger.getEffectiveLevel()) 495 496 def test_has_level_from_flags_for_trace(self): 497 self.assertEqual(log.TRACE, self.log_trace.logger.getEffectiveLevel()) 498 499 def test_child_log_has_level_of_parent_flag(self): 500 logger = log.getLogger('nova-test.foo') 501 self.assertEqual(logging.INFO, logger.logger.getEffectiveLevel()) 502 503 def test_child_log_has_level_of_parent_flag_for_trace(self): 504 logger = log.getLogger('nova-trace.foo') 505 self.assertEqual(log.TRACE, logger.logger.getEffectiveLevel()) 506 507 def test_get_loggers(self): 508 log._loggers['sentinel_log'] = mock.sentinel.sentinel_log 509 res = log.get_loggers() 510 self.assertDictEqual(log._loggers, res) 511 512 513class JSONFormatterTestCase(LogTestBase): 514 def setUp(self): 515 super(JSONFormatterTestCase, self).setUp() 516 self.log = log.getLogger('test-json') 517 self._add_handler_with_cleanup(self.log, 518 formatter=formatters.JSONFormatter) 519 self._set_log_level_with_cleanup(self.log, logging.DEBUG) 520 521 def test_json_w_context_in_extras(self): 522 test_msg = 'This is a %(test)s line' 523 test_data = {'test': 'log'} 524 local_context = _fake_context() 525 self.log.debug(test_msg, test_data, key='value', context=local_context) 526 self._validate_json_data('test_json_w_context_in_extras', test_msg, 527 test_data, local_context) 528 529 def test_json_w_fetched_global_context(self): 530 test_msg = 'This is a %(test)s line' 531 test_data = {'test': 'log'} 532 local_context = _fake_context() 533 # NOTE we're not passing the context explicitly here. But it'll add the 534 # context to the extras anyway since the call to fake_context adds the 535 # context to the thread. The context will be fetched with the 536 # _update_record_with_context call that's done in the formatter. 537 self.log.debug(test_msg, test_data, key='value') 538 self._validate_json_data('test_json_w_fetched_global_context', 539 test_msg, test_data, local_context) 540 541 def _validate_json_data(self, testname, test_msg, test_data, ctx): 542 data = jsonutils.loads(self.stream.getvalue()) 543 self.assertTrue(data) 544 self.assertIn('extra', data) 545 self.assertIn('context', data) 546 extra = data['extra'] 547 context = data['context'] 548 self.assertNotIn('context', extra) 549 self.assertEqual('value', extra['key']) 550 self.assertEqual(ctx.user, context['user']) 551 self.assertEqual(ctx.user_name, context['user_name']) 552 self.assertEqual(ctx.project_name, context['project_name']) 553 self.assertEqual('test-json', data['name']) 554 self.assertIn('request_id', context) 555 self.assertEqual(ctx.request_id, context['request_id']) 556 self.assertIn('global_request_id', context) 557 self.assertEqual(ctx.global_request_id, context['global_request_id']) 558 559 self.assertEqual(test_msg % test_data, data['message']) 560 self.assertEqual(test_msg, data['msg']) 561 self.assertEqual(test_data, data['args']) 562 563 self.assertEqual('test_log.py', data['filename']) 564 self.assertEqual(testname, data['funcname']) 565 566 self.assertEqual('DEBUG', data['levelname']) 567 self.assertEqual(logging.DEBUG, data['levelno']) 568 self.assertFalse(data['traceback']) 569 570 def test_json_exception(self): 571 test_msg = 'This is %s' 572 test_data = 'exceptional' 573 try: 574 raise Exception('This is exceptional') 575 except Exception: 576 self.log.exception(test_msg, test_data) 577 578 data = jsonutils.loads(self.stream.getvalue()) 579 self.assertTrue(data) 580 self.assertIn('extra', data) 581 self.assertEqual('test-json', data['name']) 582 583 self.assertEqual(test_msg % test_data, data['message']) 584 self.assertEqual(test_msg, data['msg']) 585 self.assertEqual([test_data], data['args']) 586 587 self.assertEqual('ERROR', data['levelname']) 588 self.assertEqual(logging.ERROR, data['levelno']) 589 self.assertTrue(data['traceback']) 590 591 def test_json_with_extra(self): 592 test_msg = 'This is a %(test)s line' 593 test_data = {'test': 'log'} 594 extra_data = {'special_user': 'user1', 595 'special_tenant': 'unicorns'} 596 self.log.debug(test_msg, test_data, key='value', extra=extra_data) 597 598 data = jsonutils.loads(self.stream.getvalue()) 599 self.assertTrue(data) 600 self.assertIn('extra', data) 601 for k, v in extra_data.items(): 602 self.assertIn(k, data['extra']) 603 self.assertEqual(v, data['extra'][k]) 604 605 def test_json_with_extra_keys(self): 606 test_msg = 'This is a %(test)s line' 607 test_data = {'test': 'log'} 608 extra_keys = ['special_tenant', 'special_user'] 609 special_tenant = 'unicorns' 610 special_user = 'user2' 611 self.log.debug(test_msg, test_data, key='value', 612 extra_keys=extra_keys, special_tenant=special_tenant, 613 special_user=special_user) 614 615 data = jsonutils.loads(self.stream.getvalue()) 616 self.assertTrue(data) 617 self.assertIn('extra', data) 618 self.assertIn(extra_keys[0], data['extra']) 619 self.assertEqual(special_tenant, data['extra'][extra_keys[0]]) 620 self.assertIn(extra_keys[1], data['extra']) 621 self.assertEqual(special_user, data['extra'][extra_keys[1]]) 622 623 def test_can_process_strings(self): 624 expected = b'\\u2622' 625 # see ContextFormatterTestCase.test_can_process_strings 626 expected = '\\\\xe2\\\\x98\\\\xa2' 627 self.log.info(b'%s', u'\u2622'.encode('utf8')) 628 self.assertIn(expected, self.stream.getvalue()) 629 630 def test_exception(self): 631 ctxt = _fake_context() 632 ctxt.request_id = str('99') 633 try: 634 raise RuntimeError('test_exception') 635 except RuntimeError: 636 self.log.warning('testing', context=ctxt) 637 data = jsonutils.loads(self.stream.getvalue()) 638 self.assertIn('error_summary', data) 639 self.assertEqual('RuntimeError: test_exception', 640 data['error_summary']) 641 642 def test_no_exception(self): 643 ctxt = _fake_context() 644 ctxt.request_id = str('99') 645 self.log.info('testing', context=ctxt) 646 data = jsonutils.loads(self.stream.getvalue()) 647 self.assertIn('error_summary', data) 648 self.assertEqual('', data['error_summary']) 649 650 def test_exception_without_exc_info_passed(self): 651 ctxt = _fake_context() 652 ctxt.request_id = str('99') 653 try: 654 raise RuntimeError('test_exception\ntraceback\nfrom\nremote error') 655 except RuntimeError: 656 self.log.warning('testing', context=ctxt) 657 data = jsonutils.loads(self.stream.getvalue()) 658 self.assertIn('error_summary', data) 659 self.assertEqual('RuntimeError: test_exception', data['error_summary']) 660 661 def test_exception_with_exc_info_passed(self): 662 ctxt = _fake_context() 663 ctxt.request_id = str('99') 664 try: 665 raise RuntimeError('test_exception\ntraceback\nfrom\nremote error') 666 except RuntimeError: 667 self.log.exception('testing', context=ctxt) 668 data = jsonutils.loads(self.stream.getvalue()) 669 self.assertIn('error_summary', data) 670 self.assertEqual('RuntimeError: test_exception' 671 '\ntraceback\nfrom\nremote error', 672 data['error_summary']) 673 674 def test_fallback(self): 675 676 class MyObject(object): 677 def __str__(self): 678 return 'str' 679 680 def __repr__(self): 681 return 'repr' 682 683 obj = MyObject() 684 self.log.debug('obj=%s', obj) 685 686 data = jsonutils.loads(self.stream.getvalue()) 687 self.assertEqual('obj=str', data['message']) 688 # Bug #1593641: If an object of record.args cannot be serialized, 689 # convert it using repr() to prevent serialization error on logging. 690 self.assertEqual(['repr'], data['args']) 691 692 def test_extra_args_filtered(self): 693 test_msg = 'This is a %(test)s line %%(unused)' 694 test_data = {'test': 'log', 'unused': 'removeme'} 695 self.log.debug(test_msg, test_data) 696 697 data = jsonutils.loads(self.stream.getvalue()) 698 self.assertNotIn('unused', data['args']) 699 700 def test_entire_dict(self): 701 test_msg = 'This is a %s dict' 702 test_data = {'test': 'log', 'other': 'value'} 703 self.log.debug(test_msg, test_data) 704 705 data = jsonutils.loads(self.stream.getvalue()) 706 self.assertEqual(test_data, data['args']) 707 708 709def get_fake_datetime(retval): 710 class FakeDateTime(datetime.datetime): 711 @classmethod 712 def fromtimestamp(cls, timestamp): 713 return retval 714 715 return FakeDateTime 716 717 718class DictStreamHandler(logging.StreamHandler): 719 """Serialize dict in order to avoid TypeError in python 3. It is needed for 720 FluentFormatterTestCase. 721 """ 722 def emit(self, record): 723 try: 724 msg = self.format(record) 725 jsonutils.dump(msg, self.stream) 726 self.stream.flush() 727 except AttributeError: 728 self.handleError(record) 729 730 731class FluentFormatterTestCase(LogTestBase): 732 def setUp(self): 733 super(FluentFormatterTestCase, self).setUp() 734 self.log = log.getLogger('test-fluent') 735 self._add_handler_with_cleanup(self.log, 736 handler=DictStreamHandler, 737 formatter=formatters.FluentFormatter) 738 self._set_log_level_with_cleanup(self.log, logging.DEBUG) 739 740 def test_fluent(self): 741 test_msg = 'This is a %(test)s line' 742 test_data = {'test': 'log'} 743 local_context = _fake_context() 744 self.log.debug(test_msg, test_data, key='value', context=local_context) 745 746 data = jsonutils.loads(self.stream.getvalue()) 747 self.assertIn('lineno', data) 748 self.assertIn('extra', data) 749 extra = data['extra'] 750 context = data['context'] 751 self.assertEqual('value', extra['key']) 752 self.assertEqual(local_context.user, context['user']) 753 self.assertEqual('test-fluent', data['name']) 754 755 self.assertIn('request_id', context) 756 self.assertEqual(local_context.request_id, context['request_id']) 757 self.assertIn('global_request_id', context) 758 self.assertEqual(local_context.global_request_id, 759 context['global_request_id']) 760 761 self.assertEqual(test_msg % test_data, data['message']) 762 763 self.assertEqual('test_log.py', data['filename']) 764 self.assertEqual('test_fluent', data['funcname']) 765 766 self.assertEqual('DEBUG', data['level']) 767 self.assertFalse(data['traceback']) 768 769 def test_exception(self): 770 local_context = _fake_context() 771 try: 772 raise RuntimeError('test_exception') 773 except RuntimeError: 774 self.log.warning('testing', context=local_context) 775 data = jsonutils.loads(self.stream.getvalue()) 776 self.assertIn('error_summary', data) 777 self.assertEqual('RuntimeError: test_exception', 778 data['error_summary']) 779 780 def test_no_exception(self): 781 local_context = _fake_context() 782 self.log.info('testing', context=local_context) 783 data = jsonutils.loads(self.stream.getvalue()) 784 self.assertIn('error_summary', data) 785 self.assertEqual('', data['error_summary']) 786 787 def test_json_exception(self): 788 test_msg = 'This is %s' 789 test_data = 'exceptional' 790 try: 791 raise Exception('This is exceptional') 792 except Exception: 793 self.log.exception(test_msg, test_data) 794 795 data = jsonutils.loads(self.stream.getvalue()) 796 self.assertTrue(data) 797 self.assertIn('extra', data) 798 self.assertEqual('test-fluent', data['name']) 799 800 self.assertEqual(test_msg % test_data, data['message']) 801 802 self.assertEqual('ERROR', data['level']) 803 self.assertTrue(data['traceback']) 804 805 806class ContextFormatterTestCase(LogTestBase): 807 def setUp(self): 808 super(ContextFormatterTestCase, self).setUp() 809 self.config(logging_context_format_string="HAS CONTEXT " 810 "[%(request_id)s]: " 811 "%(message)s", 812 logging_default_format_string="NOCTXT: %(message)s", 813 logging_debug_format_suffix="--DBG") 814 self.log = log.getLogger('') # obtain root logger instead of 'unknown' 815 self._add_handler_with_cleanup(self.log) 816 self._set_log_level_with_cleanup(self.log, logging.DEBUG) 817 self.trans_fixture = self.useFixture(fixture_trans.Translation()) 818 819 def test_uncontextualized_log(self): 820 message = 'foo' 821 self.log.info(message) 822 self.assertEqual("NOCTXT: %s\n" % message, self.stream.getvalue()) 823 824 def test_contextualized_log(self): 825 ctxt = _fake_context() 826 message = 'bar' 827 self.log.info(message, context=ctxt) 828 expected = 'HAS CONTEXT [%s]: %s\n' % (ctxt.request_id, message) 829 self.assertEqual(expected, self.stream.getvalue()) 830 831 def test_context_is_taken_from_tls_variable(self): 832 ctxt = _fake_context() 833 message = 'bar' 834 self.log.info(message) 835 expected = "HAS CONTEXT [%s]: %s\n" % (ctxt.request_id, message) 836 self.assertEqual(expected, self.stream.getvalue()) 837 838 def test_contextual_information_is_imparted_to_3rd_party_log_records(self): 839 ctxt = _fake_context() 840 sa_log = logging.getLogger('sqlalchemy.engine') 841 sa_log.setLevel(logging.INFO) 842 message = 'emulate logging within sqlalchemy' 843 sa_log.info(message) 844 845 expected = ('HAS CONTEXT [%s]: %s\n' % (ctxt.request_id, message)) 846 self.assertEqual(expected, self.stream.getvalue()) 847 848 def test_message_logging_3rd_party_log_records(self): 849 ctxt = _fake_context() 850 ctxt.request_id = str('99') 851 sa_log = logging.getLogger('sqlalchemy.engine') 852 sa_log.setLevel(logging.INFO) 853 message = self.trans_fixture.lazy('test ' + chr(128)) 854 sa_log.info(message) 855 856 expected = ('HAS CONTEXT [%s]: %s\n' % (ctxt.request_id, 857 str(message))) 858 self.assertEqual(expected, self.stream.getvalue()) 859 860 def test_debugging_log(self): 861 message = 'baz' 862 self.log.debug(message) 863 self.assertEqual("NOCTXT: %s --DBG\n" % message, 864 self.stream.getvalue()) 865 866 def test_message_logging(self): 867 # NOTE(luisg): Logging message objects with unicode objects 868 # may cause trouble by the logging mechanism trying to coerce 869 # the Message object, with a wrong encoding. This test case 870 # tests that problem does not occur. 871 ctxt = _fake_context() 872 ctxt.request_id = str('99') 873 message = self.trans_fixture.lazy('test ' + chr(128)) 874 self.log.info(message, context=ctxt) 875 expected = "HAS CONTEXT [%s]: %s\n" % (ctxt.request_id, 876 str(message)) 877 self.assertEqual(expected, self.stream.getvalue()) 878 879 def test_exception_logging(self): 880 # NOTE(dhellmann): If there is an exception and %(error_summary)s 881 # does not appear in the format string, ensure that it is 882 # appended to the end of the log lines. 883 ctxt = _fake_context() 884 ctxt.request_id = str('99') 885 message = self.trans_fixture.lazy('test ' + chr(128)) 886 try: 887 raise RuntimeError('test_exception_logging') 888 except RuntimeError: 889 self.log.warning(message, context=ctxt) 890 expected = 'RuntimeError: test_exception_logging\n' 891 self.assertTrue(self.stream.getvalue().endswith(expected)) 892 893 def test_skip_logging_builtin_exceptions(self): 894 # NOTE(dhellmann): Several of the built-in exception types 895 # should not be automatically added to the log output. 896 ctxt = _fake_context() 897 ctxt.request_id = str('99') 898 message = self.trans_fixture.lazy('test ' + chr(128)) 899 ignored_exceptions = [ 900 ValueError, TypeError, KeyError, AttributeError, ImportError 901 ] 902 for ignore in ignored_exceptions: 903 try: 904 raise ignore('test_exception_logging') 905 except ignore as e: 906 self.log.warning(message, context=ctxt) 907 expected = '{}: {}'.format(e.__class__.__name__, e) 908 self.assertNotIn(expected, self.stream.getvalue()) 909 910 def test_exception_logging_format_string(self): 911 # NOTE(dhellmann): If the format string includes 912 # %(error_summary)s then ensure the exception message ends up in 913 # that position in the output. 914 self.config(logging_context_format_string="A %(error_summary)s B") 915 ctxt = _fake_context() 916 ctxt.request_id = str('99') 917 message = self.trans_fixture.lazy('test ' + chr(128)) 918 try: 919 raise RuntimeError('test_exception_logging') 920 except RuntimeError: 921 self.log.warning(message, context=ctxt) 922 expected = 'A RuntimeError: test_exception_logging' 923 self.assertTrue(self.stream.getvalue().startswith(expected)) 924 925 def test_no_exception_logging_format_string(self): 926 # NOTE(dhellmann): If there is no exception but the format 927 # string includes %(error_summary)s then ensure the "-" is 928 # inserted. 929 self.config(logging_context_format_string="%(error_summary)s") 930 ctxt = _fake_context() 931 ctxt.request_id = str('99') 932 message = self.trans_fixture.lazy('test ' + chr(128)) 933 self.log.info(message, context=ctxt) 934 expected = '-\n' 935 self.assertTrue(self.stream.getvalue().startswith(expected)) 936 937 def test_unicode_conversion_in_adapter(self): 938 ctxt = _fake_context() 939 ctxt.request_id = str('99') 940 message = "Exception is (%s)" 941 ex = Exception(self.trans_fixture.lazy('test' + chr(128))) 942 self.log.debug(message, ex, context=ctxt) 943 message = str(message) % ex 944 expected = "HAS CONTEXT [%s]: %s --DBG\n" % (ctxt.request_id, 945 message) 946 self.assertEqual(expected, self.stream.getvalue()) 947 948 def test_unicode_conversion_in_formatter(self): 949 ctxt = _fake_context() 950 ctxt.request_id = str('99') 951 no_adapt_log = logging.getLogger('no_adapt') 952 no_adapt_log.setLevel(logging.INFO) 953 message = "Exception is (%s)" 954 ex = Exception(self.trans_fixture.lazy('test' + chr(128))) 955 no_adapt_log.info(message, ex) 956 message = str(message) % ex 957 expected = "HAS CONTEXT [%s]: %s\n" % (ctxt.request_id, 958 message) 959 self.assertEqual(expected, self.stream.getvalue()) 960 961 def test_user_identity_logging(self): 962 self.config(logging_context_format_string="HAS CONTEXT " 963 "[%(request_id)s " 964 "%(user_identity)s]: " 965 "%(message)s") 966 ctxt = _fake_context() 967 ctxt.request_id = u'99' 968 message = 'test' 969 self.log.info(message, context=ctxt) 970 expected = ("HAS CONTEXT [%s %s %s %s %s %s]: %s\n" % 971 (ctxt.request_id, ctxt.user, ctxt.tenant, ctxt.domain, 972 ctxt.user_domain, ctxt.project_domain, 973 str(message))) 974 self.assertEqual(expected, self.stream.getvalue()) 975 976 def test_user_identity_logging_set_format(self): 977 self.config(logging_context_format_string="HAS CONTEXT " 978 "[%(request_id)s " 979 "%(user_identity)s]: " 980 "%(message)s", 981 logging_user_identity_format="%(user)s " 982 "%(tenant)s") 983 ctxt = _fake_context() 984 ctxt.request_id = u'99' 985 message = 'test' 986 self.log.info(message, context=ctxt) 987 expected = ("HAS CONTEXT [%s %s %s]: %s\n" % 988 (ctxt.request_id, ctxt.user, ctxt.tenant, 989 str(message))) 990 self.assertEqual(expected, self.stream.getvalue()) 991 992 @mock.patch("datetime.datetime", 993 get_fake_datetime( 994 datetime.datetime(2015, 12, 16, 13, 54, 26, 517893))) 995 @mock.patch("dateutil.tz.tzlocal", new=mock.Mock(return_value=tz.tzutc())) 996 def test_rfc5424_isotime_format(self): 997 self.config(logging_default_format_string="%(isotime)s %(message)s") 998 999 message = "test" 1000 expected = "2015-12-16T13:54:26.517893+00:00 %s\n" % message 1001 1002 self.log.info(message) 1003 1004 self.assertEqual(expected, self.stream.getvalue()) 1005 1006 @mock.patch("datetime.datetime", 1007 get_fake_datetime( 1008 datetime.datetime(2015, 12, 16, 13, 54, 26))) 1009 @mock.patch("time.time", new=mock.Mock(return_value=1450274066.000000)) 1010 @mock.patch("dateutil.tz.tzlocal", new=mock.Mock(return_value=tz.tzutc())) 1011 def test_rfc5424_isotime_format_no_microseconds(self): 1012 self.config(logging_default_format_string="%(isotime)s %(message)s") 1013 1014 message = "test" 1015 expected = "2015-12-16T13:54:26.000000+00:00 %s\n" % message 1016 1017 self.log.info(message) 1018 1019 self.assertEqual(expected, self.stream.getvalue()) 1020 1021 def test_can_process_strings(self): 1022 expected = b'\xe2\x98\xa2' 1023 # logging format string should be unicode string 1024 # or it will fail and inserting byte string in unicode string 1025 # causes such formatting 1026 expected = '\\xe2\\x98\\xa2' 1027 self.log.info(b'%s', u'\u2622'.encode('utf8')) 1028 self.assertIn(expected, self.stream.getvalue()) 1029 1030 def test_dict_args_with_unicode(self): 1031 msg = '%(thing)s' 1032 arg = {'thing': '\xc6\x91\xc6\xa1\xc6\xa1'} 1033 self.log.info(msg, arg) 1034 self.assertIn(arg['thing'], self.stream.getvalue()) 1035 1036 1037class ExceptionLoggingTestCase(LogTestBase): 1038 """Test that Exceptions are logged.""" 1039 1040 def test_excepthook_logs_exception(self): 1041 product_name = 'somename' 1042 exc_log = log.getLogger(product_name) 1043 1044 self._add_handler_with_cleanup(exc_log) 1045 excepthook = log._create_logging_excepthook(product_name) 1046 1047 try: 1048 raise Exception('Some error happened') 1049 except Exception: 1050 excepthook(*sys.exc_info()) 1051 1052 expected_string = ("CRITICAL somename [-] Unhandled error: " 1053 "Exception: Some error happened") 1054 self.assertIn(expected_string, self.stream.getvalue(), 1055 message="Exception is not logged") 1056 1057 def test_excepthook_installed(self): 1058 log.setup(self.CONF, "test_excepthook_installed") 1059 self.assertTrue(sys.excepthook != sys.__excepthook__) 1060 1061 @mock.patch("datetime.datetime", 1062 get_fake_datetime( 1063 datetime.datetime(2015, 12, 16, 13, 54, 26, 517893))) 1064 @mock.patch("dateutil.tz.tzlocal", new=mock.Mock(return_value=tz.tzutc())) 1065 def test_rfc5424_isotime_format(self): 1066 self.config( 1067 logging_default_format_string="%(isotime)s %(message)s", 1068 logging_exception_prefix="%(isotime)s ", 1069 ) 1070 1071 product_name = 'somename' 1072 exc_log = log.getLogger(product_name) 1073 1074 self._add_handler_with_cleanup(exc_log) 1075 excepthook = log._create_logging_excepthook(product_name) 1076 1077 message = 'Some error happened' 1078 try: 1079 raise Exception(message) 1080 except Exception: 1081 excepthook(*sys.exc_info()) 1082 1083 expected_string = ("2015-12-16T13:54:26.517893+00:00 " 1084 "Exception: %s" % message) 1085 self.assertIn(expected_string, 1086 self.stream.getvalue()) 1087 1088 1089class FancyRecordTestCase(LogTestBase): 1090 """Test how we handle fancy record keys that are not in the 1091 base python logging. 1092 """ 1093 1094 def setUp(self): 1095 super(FancyRecordTestCase, self).setUp() 1096 # NOTE(sdague): use the different formatters to demonstrate format 1097 # string with valid fancy keys and without. Slightly hacky, but given 1098 # the way log objects layer up seemed to be most concise approach 1099 self.config(logging_context_format_string="%(color)s " 1100 "[%(request_id)s]: " 1101 "%(instance)s" 1102 "%(resource)s" 1103 "%(message)s", 1104 logging_default_format_string="%(missing)s: %(message)s") 1105 self.colorlog = log.getLogger() 1106 self._add_handler_with_cleanup(self.colorlog, handlers.ColorHandler) 1107 self._set_log_level_with_cleanup(self.colorlog, logging.DEBUG) 1108 1109 def test_unsupported_key_in_log_msg(self): 1110 # NOTE(sdague): exception logging bypasses the main stream 1111 # and goes to stderr. Suggests on a better way to do this are 1112 # welcomed. 1113 error = sys.stderr 1114 sys.stderr = io.StringIO() 1115 1116 self.colorlog.info("foo") 1117 self.assertNotEqual(-1, 1118 sys.stderr.getvalue().find("KeyError: 'missing'")) 1119 1120 sys.stderr = error 1121 1122 def _validate_keys(self, ctxt, keyed_log_string): 1123 infocolor = handlers.ColorHandler.LEVEL_COLORS[logging.INFO] 1124 warncolor = handlers.ColorHandler.LEVEL_COLORS[logging.WARN] 1125 info_msg = 'info' 1126 warn_msg = 'warn' 1127 infoexpected = "%s %s %s" % (infocolor, keyed_log_string, info_msg) 1128 warnexpected = "%s %s %s" % (warncolor, keyed_log_string, warn_msg) 1129 1130 self.colorlog.info(info_msg, context=ctxt) 1131 self.assertIn(infoexpected, self.stream.getvalue()) 1132 self.assertEqual('\033[00;36m', infocolor) 1133 1134 self.colorlog.warn(warn_msg, context=ctxt) 1135 self.assertIn(infoexpected, self.stream.getvalue()) 1136 self.assertIn(warnexpected, self.stream.getvalue()) 1137 self.assertEqual('\033[01;33m', warncolor) 1138 1139 def test_fancy_key_in_log_msg(self): 1140 ctxt = _fake_context() 1141 self._validate_keys(ctxt, '[%s]:' % ctxt.request_id) 1142 1143 def test_instance_key_in_log_msg(self): 1144 ctxt = _fake_context() 1145 ctxt.resource_uuid = '1234' 1146 self._validate_keys(ctxt, ('[%s]: [instance: %s]' % 1147 (ctxt.request_id, ctxt.resource_uuid))) 1148 1149 def test_resource_key_in_log_msg(self): 1150 color = handlers.ColorHandler.LEVEL_COLORS[logging.INFO] 1151 ctxt = _fake_context() 1152 resource = 'resource-202260f9-1224-490d-afaf-6a744c13141f' 1153 fake_resource = {'name': resource} 1154 message = 'info' 1155 self.colorlog.info(message, context=ctxt, resource=fake_resource) 1156 expected = ('%s [%s]: [%s] %s\033[00m\n' % 1157 (color, ctxt.request_id, resource, message)) 1158 self.assertEqual(expected, self.stream.getvalue()) 1159 1160 def test_resource_key_dict_in_log_msg(self): 1161 color = handlers.ColorHandler.LEVEL_COLORS[logging.INFO] 1162 ctxt = _fake_context() 1163 type = 'fake_resource' 1164 resource_id = '202260f9-1224-490d-afaf-6a744c13141f' 1165 fake_resource = {'type': type, 1166 'id': resource_id} 1167 message = 'info' 1168 self.colorlog.info(message, context=ctxt, resource=fake_resource) 1169 expected = ('%s [%s]: [%s-%s] %s\033[00m\n' % 1170 (color, ctxt.request_id, type, resource_id, message)) 1171 self.assertEqual(expected, self.stream.getvalue()) 1172 1173 1174class InstanceRecordTestCase(LogTestBase): 1175 def setUp(self): 1176 super(InstanceRecordTestCase, self).setUp() 1177 self.config(logging_context_format_string="[%(request_id)s]: " 1178 "%(instance)s" 1179 "%(resource)s" 1180 "%(message)s", 1181 logging_default_format_string="%(instance)s" 1182 "%(resource)s" 1183 "%(message)s") 1184 self.log = log.getLogger() 1185 self._add_handler_with_cleanup(self.log) 1186 self._set_log_level_with_cleanup(self.log, logging.DEBUG) 1187 1188 def test_instance_dict_in_context_log_msg(self): 1189 ctxt = _fake_context() 1190 uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3' 1191 fake_resource = {'uuid': uuid} 1192 message = 'info' 1193 self.log.info(message, context=ctxt, instance=fake_resource) 1194 expected = '[instance: %s]' % uuid 1195 self.assertIn(expected, self.stream.getvalue()) 1196 1197 def test_instance_dict_in_default_log_msg(self): 1198 uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3' 1199 fake_resource = {'uuid': uuid} 1200 message = 'info' 1201 self.log.info(message, instance=fake_resource) 1202 expected = '[instance: %s]' % uuid 1203 self.assertIn(expected, self.stream.getvalue()) 1204 1205 def test_instance_uuid_as_arg_in_context_log_msg(self): 1206 ctxt = _fake_context() 1207 uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3' 1208 message = 'info' 1209 self.log.info(message, context=ctxt, instance_uuid=uuid) 1210 expected = '[instance: %s]' % uuid 1211 self.assertIn(expected, self.stream.getvalue()) 1212 1213 def test_instance_uuid_as_arg_in_default_log_msg(self): 1214 uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3' 1215 message = 'info' 1216 self.log.info(message, instance_uuid=uuid) 1217 expected = '[instance: %s]' % uuid 1218 self.assertIn(expected, self.stream.getvalue()) 1219 1220 def test_instance_uuid_from_context_in_context_log_msg(self): 1221 ctxt = _fake_context() 1222 ctxt.instance_uuid = 'CCCCCCCC-8A12-4C53-A736-D7A1C36A62F3' 1223 message = 'info' 1224 self.log.info(message, context=ctxt) 1225 expected = '[instance: %s]' % ctxt.instance_uuid 1226 self.assertIn(expected, self.stream.getvalue()) 1227 1228 def test_resource_uuid_from_context_in_context_log_msg(self): 1229 ctxt = _fake_context() 1230 ctxt.resource_uuid = 'RRRRRRRR-8A12-4C53-A736-D7A1C36A62F3' 1231 message = 'info' 1232 self.log.info(message, context=ctxt) 1233 expected = '[instance: %s]' % ctxt.resource_uuid 1234 self.assertIn(expected, self.stream.getvalue()) 1235 1236 def test_instance_from_context_in_context_log_msg(self): 1237 # NOTE: instance when passed in a context object is just a uuid. 1238 # When passed to the log record, it is a dict. 1239 ctxt = _fake_context() 1240 ctxt.instance = 'IIIIIIII-8A12-4C53-A736-D7A1C36A62F3' 1241 message = 'info' 1242 self.log.info(message, context=ctxt) 1243 expected = '[instance: %s]' % ctxt.instance 1244 self.assertIn(expected, self.stream.getvalue()) 1245 1246 1247class TraceLevelTestCase(LogTestBase): 1248 def setUp(self): 1249 super(TraceLevelTestCase, self).setUp() 1250 self.config(logging_context_format_string="%(message)s") 1251 self.mylog = log.getLogger() 1252 self._add_handler_with_cleanup(self.mylog) 1253 self._set_log_level_with_cleanup(self.mylog, log.TRACE) 1254 1255 def test_trace_log_msg(self): 1256 ctxt = _fake_context() 1257 message = 'my trace message' 1258 self.mylog.trace(message, context=ctxt) 1259 self.assertEqual('%s\n' % message, self.stream.getvalue()) 1260 1261 1262class DomainTestCase(LogTestBase): 1263 def setUp(self): 1264 super(DomainTestCase, self).setUp() 1265 self.config(logging_context_format_string="[%(request_id)s]: " 1266 "%(user_identity)s " 1267 "%(message)s") 1268 self.mylog = log.getLogger() 1269 self._add_handler_with_cleanup(self.mylog) 1270 self._set_log_level_with_cleanup(self.mylog, logging.DEBUG) 1271 1272 def _validate_keys(self, ctxt, keyed_log_string): 1273 info_message = 'info' 1274 infoexpected = "%s %s\n" % (keyed_log_string, info_message) 1275 warn_message = 'warn' 1276 warnexpected = "%s %s\n" % (keyed_log_string, warn_message) 1277 1278 self.mylog.info(info_message, context=ctxt) 1279 self.assertEqual(infoexpected, self.stream.getvalue()) 1280 1281 self.mylog.warn(warn_message, context=ctxt) 1282 self.assertEqual(infoexpected + warnexpected, self.stream.getvalue()) 1283 1284 def test_domain_in_log_msg(self): 1285 ctxt = _fake_context() 1286 user_identity = ctxt.get_logging_values()['user_identity'] 1287 self.assertIn(ctxt.domain, user_identity) 1288 self.assertIn(ctxt.project_domain, user_identity) 1289 self.assertIn(ctxt.user_domain, user_identity) 1290 self._validate_keys(ctxt, ('[%s]: %s' % 1291 (ctxt.request_id, user_identity))) 1292 1293 1294class SetDefaultsTestCase(BaseTestCase): 1295 class TestConfigOpts(cfg.ConfigOpts): 1296 def __call__(self, args=None): 1297 return cfg.ConfigOpts.__call__(self, 1298 args=args, 1299 prog='test', 1300 version='1.0', 1301 usage='%(prog)s FOO BAR', 1302 default_config_files=[]) 1303 1304 def setUp(self): 1305 super(SetDefaultsTestCase, self).setUp() 1306 self.conf = self.TestConfigOpts() 1307 self.conf.register_opts(_options.log_opts) 1308 self.conf.register_cli_opts(_options.logging_cli_opts) 1309 1310 self._orig_defaults = dict([(o.dest, o.default) 1311 for o in _options.log_opts]) 1312 self.addCleanup(self._restore_log_defaults) 1313 1314 def _restore_log_defaults(self): 1315 for opt in _options.log_opts: 1316 opt.default = self._orig_defaults[opt.dest] 1317 1318 def test_default_log_level_to_none(self): 1319 log.set_defaults(logging_context_format_string=None, 1320 default_log_levels=None) 1321 self.conf([]) 1322 self.assertEqual(_options.DEFAULT_LOG_LEVELS, 1323 self.conf.default_log_levels) 1324 1325 def test_default_log_level_method(self): 1326 self.assertEqual(_options.DEFAULT_LOG_LEVELS, 1327 log.get_default_log_levels()) 1328 1329 def test_change_default(self): 1330 my_default = '%(asctime)s %(levelname)s %(name)s [%(request_id)s '\ 1331 '%(user_id)s %(project)s] %(instance)s'\ 1332 '%(message)s' 1333 log.set_defaults(logging_context_format_string=my_default) 1334 self.conf([]) 1335 self.assertEqual(self.conf.logging_context_format_string, my_default) 1336 1337 def test_change_default_log_level(self): 1338 package_log_level = 'foo=bar' 1339 log.set_defaults(default_log_levels=[package_log_level]) 1340 self.conf([]) 1341 self.assertEqual([package_log_level], self.conf.default_log_levels) 1342 self.assertIsNotNone(self.conf.logging_context_format_string) 1343 1344 def test_tempest_set_log_file(self): 1345 log_file = 'foo.log' 1346 log.tempest_set_log_file(log_file) 1347 self.addCleanup(log.tempest_set_log_file, None) 1348 log.set_defaults() 1349 self.conf([]) 1350 self.assertEqual(log_file, self.conf.log_file) 1351 1352 def test_log_file_defaults_to_none(self): 1353 log.set_defaults() 1354 self.conf([]) 1355 self.assertIsNone(self.conf.log_file) 1356 1357 1358@testtools.skipIf(platform.system() != 'Linux', 1359 'pyinotify library works on Linux platform only.') 1360class FastWatchedFileHandlerTestCase(BaseTestCase): 1361 1362 def setUp(self): 1363 super(FastWatchedFileHandlerTestCase, self).setUp() 1364 1365 def _config(self): 1366 os_level, log_path = tempfile.mkstemp() 1367 log_dir_path = os.path.dirname(log_path) 1368 log_file_path = os.path.basename(log_path) 1369 self.CONF(['--log-dir', log_dir_path, '--log-file', log_file_path]) 1370 self.config(use_stderr=False) 1371 self.config(watch_log_file=True) 1372 log.setup(self.CONF, 'test', 'test') 1373 return log_path 1374 1375 def test_instantiate(self): 1376 self._config() 1377 logger = log._loggers[None].logger 1378 self.assertEqual(1, len(logger.handlers)) 1379 from oslo_log import watchers 1380 self.assertIsInstance(logger.handlers[0], 1381 watchers.FastWatchedFileHandler) 1382 1383 def test_log(self): 1384 log_path = self._config() 1385 logger = log._loggers[None].logger 1386 text = 'Hello World!' 1387 logger.info(text) 1388 with open(log_path, 'r') as f: 1389 file_content = f.read() 1390 self.assertIn(text, file_content) 1391 1392 def test_move(self): 1393 log_path = self._config() 1394 os_level_dst, log_path_dst = tempfile.mkstemp() 1395 os.rename(log_path, log_path_dst) 1396 time.sleep(6) 1397 self.assertTrue(os.path.exists(log_path)) 1398 1399 def test_remove(self): 1400 log_path = self._config() 1401 os.remove(log_path) 1402 time.sleep(6) 1403 self.assertTrue(os.path.exists(log_path)) 1404 1405 1406class MutateTestCase(BaseTestCase): 1407 def setUp(self): 1408 super(MutateTestCase, self).setUp() 1409 if hasattr(log._load_log_config, 'old_time'): 1410 del log._load_log_config.old_time 1411 1412 def setup_confs(self, *confs): 1413 paths = self.create_tempfiles( 1414 ('conf_%d' % i, conf) for i, conf in enumerate(confs)) 1415 self.CONF(['--config-file', paths[0]]) 1416 return paths 1417 1418 def test_debug(self): 1419 paths = self.setup_confs( 1420 "[DEFAULT]\ndebug = false\n", 1421 "[DEFAULT]\ndebug = true\n") 1422 log_root = log.getLogger(None).logger 1423 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1424 self.assertEqual(False, self.CONF.debug) 1425 self.assertEqual(log.INFO, log_root.getEffectiveLevel()) 1426 1427 shutil.copy(paths[1], paths[0]) 1428 self.CONF.mutate_config_files() 1429 1430 self.assertEqual(True, self.CONF.debug) 1431 self.assertEqual(log.DEBUG, log_root.getEffectiveLevel()) 1432 1433 @mock.patch.object(logging.config, "fileConfig") 1434 def test_log_config_append(self, mock_fileConfig): 1435 logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] 1436 paths = self.setup_confs( 1437 "[DEFAULT]\nlog_config_append = no_exist\n", 1438 "[DEFAULT]\nlog_config_append = %s\n" % logini) 1439 self.assertRaises(log.LogConfigError, log.setup, self.CONF, '') 1440 self.assertFalse(mock_fileConfig.called) 1441 1442 shutil.copy(paths[1], paths[0]) 1443 self.CONF.mutate_config_files() 1444 1445 mock_fileConfig.assert_called_once_with( 1446 logini, disable_existing_loggers=False) 1447 1448 @mock.patch.object(logging.config, "fileConfig") 1449 def test_log_config_append_no_touch(self, mock_fileConfig): 1450 logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] 1451 self.setup_confs("[DEFAULT]\nlog_config_append = %s\n" % logini) 1452 log.setup(self.CONF, '') 1453 mock_fileConfig.assert_called_once_with( 1454 logini, disable_existing_loggers=False) 1455 mock_fileConfig.reset_mock() 1456 1457 self.CONF.mutate_config_files() 1458 1459 self.assertFalse(mock_fileConfig.called) 1460 1461 @mock.patch.object(logging.config, "fileConfig") 1462 def test_log_config_append_touch(self, mock_fileConfig): 1463 logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] 1464 self.setup_confs("[DEFAULT]\nlog_config_append = %s\n" % logini) 1465 log.setup(self.CONF, '') 1466 mock_fileConfig.assert_called_once_with( 1467 logini, disable_existing_loggers=False) 1468 mock_fileConfig.reset_mock() 1469 1470 # No thread sync going on here, just ensure the mtimes are different 1471 time.sleep(1) 1472 os.utime(logini, None) 1473 self.CONF.mutate_config_files() 1474 1475 mock_fileConfig.assert_called_once_with( 1476 logini, disable_existing_loggers=False) 1477 1478 def mk_log_config(self, data): 1479 """Turns a dictConfig-like structure into one suitable for fileConfig. 1480 1481 The schema is not validated as this is a test helper not production 1482 code. Garbage in, garbage out. Particularly, don't try to use filters, 1483 fileConfig doesn't support them. 1484 1485 Handler args must be passed like 'args': (1, 2). dictConfig passes 1486 keys by keyword name and fileConfig passes them by position so 1487 accepting the dictConfig form makes it nigh impossible to produce the 1488 fileConfig form. 1489 1490 I traverse dicts by sorted keys for output stability but it doesn't 1491 matter if defaulted keys are out of order. 1492 """ 1493 lines = [] 1494 for section in ['formatters', 'handlers', 'loggers']: 1495 items = data.get(section, {}) 1496 keys = sorted(items) 1497 skeys = ",".join(keys) 1498 if section == 'loggers' and 'root' in data: 1499 skeys = ("root," + skeys) if skeys else "root" 1500 lines.extend(["[%s]" % section, 1501 "keys=%s" % skeys]) 1502 for key in keys: 1503 lines.extend(["", 1504 "[%s_%s]" % (section[:-1], key)]) 1505 item = items[key] 1506 lines.extend("%s=%s" % (k, item[k]) for k in sorted(item)) 1507 if section == 'handlers': 1508 if 'args' not in item: 1509 lines.append("args=()") 1510 elif section == 'loggers': 1511 lines.append("qualname=%s" % key) 1512 if 'handlers' not in item: 1513 lines.append("handlers=") 1514 lines.append("") 1515 root = data.get('root', {}) 1516 if root: 1517 lines.extend(["[logger_root]"]) 1518 lines.extend("%s=%s" % (k, root[k]) for k in sorted(root)) 1519 if 'handlers' not in root: 1520 lines.append("handlers=") 1521 return "\n".join(lines) 1522 1523 def test_mk_log_config_full(self): 1524 data = {'loggers': {'aaa': {'level': 'INFO'}, 1525 'bbb': {'level': 'WARN', 1526 'propagate': False}}, 1527 'handlers': {'aaa': {'level': 'INFO'}, 1528 'bbb': {'level': 'WARN', 1529 'propagate': False, 1530 'args': (1, 2)}}, 1531 'formatters': {'aaa': {'level': 'INFO'}, 1532 'bbb': {'level': 'WARN', 1533 'propagate': False}}, 1534 'root': {'level': 'INFO', 1535 'handlers': 'aaa'}, 1536 } 1537 full = """[formatters] 1538keys=aaa,bbb 1539 1540[formatter_aaa] 1541level=INFO 1542 1543[formatter_bbb] 1544level=WARN 1545propagate=False 1546 1547[handlers] 1548keys=aaa,bbb 1549 1550[handler_aaa] 1551level=INFO 1552args=() 1553 1554[handler_bbb] 1555args=(1, 2) 1556level=WARN 1557propagate=False 1558 1559[loggers] 1560keys=root,aaa,bbb 1561 1562[logger_aaa] 1563level=INFO 1564qualname=aaa 1565handlers= 1566 1567[logger_bbb] 1568level=WARN 1569propagate=False 1570qualname=bbb 1571handlers= 1572 1573[logger_root] 1574handlers=aaa 1575level=INFO""" 1576 self.assertEqual(full, self.mk_log_config(data)) 1577 1578 def test_mk_log_config_empty(self): 1579 """Ensure mk_log_config tolerates missing bits""" 1580 empty = """[formatters] 1581keys= 1582 1583[handlers] 1584keys= 1585 1586[loggers] 1587keys= 1588""" 1589 self.assertEqual(empty, self.mk_log_config({})) 1590 1591 @contextmanager 1592 def mutate_conf(self, conf1, conf2): 1593 loginis = self.create_tempfiles([ 1594 ('log1.ini', self.mk_log_config(conf1)), 1595 ('log2.ini', self.mk_log_config(conf2))]) 1596 confs = self.setup_confs( 1597 "[DEFAULT]\nlog_config_append = %s\n" % loginis[0], 1598 "[DEFAULT]\nlog_config_append = %s\n" % loginis[1]) 1599 log.setup(self.CONF, '') 1600 1601 yield loginis, confs 1602 shutil.copy(confs[1], confs[0]) 1603 # prevent the mtime ever matching 1604 os.utime(self.CONF.log_config_append, (0, 0)) 1605 self.CONF.mutate_config_files() 1606 1607 @mock.patch.object(logging.config, "fileConfig") 1608 def test_log_config_append_change_file(self, mock_fileConfig): 1609 with self.mutate_conf({}, {}) as (loginis, confs): 1610 mock_fileConfig.assert_called_once_with( 1611 loginis[0], disable_existing_loggers=False) 1612 mock_fileConfig.reset_mock() 1613 1614 mock_fileConfig.assert_called_once_with( 1615 loginis[1], disable_existing_loggers=False) 1616 1617 def set_root_stream(self): 1618 root = logging.getLogger() 1619 self.assertEqual(1, len(root.handlers)) 1620 handler = root.handlers[0] 1621 handler.stream = io.StringIO() 1622 return handler.stream 1623 1624 def test_remove_handler(self): 1625 fake_handler = {'class': 'logging.StreamHandler', 1626 'args': ()} 1627 conf1 = {'root': {'handlers': 'fake'}, 1628 'handlers': {'fake': fake_handler}} 1629 conf2 = {'root': {'handlers': ''}} 1630 with self.mutate_conf(conf1, conf2) as (loginis, confs): 1631 stream = self.set_root_stream() 1632 root = logging.getLogger() 1633 root.error("boo") 1634 self.assertEqual("boo\n", stream.getvalue()) 1635 stream.truncate(0) 1636 root.error("boo") 1637 self.assertEqual("", stream.getvalue()) 1638 1639 def test_remove_logger(self): 1640 fake_handler = {'class': 'logging.StreamHandler'} 1641 fake_logger = {'level': 'WARN'} 1642 conf1 = {'root': {'handlers': 'fake'}, 1643 'handlers': {'fake': fake_handler}, 1644 'loggers': {'a.a': fake_logger}} 1645 conf2 = {'root': {'handlers': 'fake'}, 1646 'handlers': {'fake': fake_handler}} 1647 stream = io.StringIO() 1648 with self.mutate_conf(conf1, conf2) as (loginis, confs): 1649 stream = self.set_root_stream() 1650 log = logging.getLogger("a.a") 1651 log.info("info") 1652 log.warn("warn") 1653 self.assertEqual("warn\n", stream.getvalue()) 1654 stream = self.set_root_stream() 1655 log.info("info") 1656 log.warn("warn") 1657 self.assertEqual("info\nwarn\n", stream.getvalue()) 1658 1659 1660class LogConfigOptsTestCase(BaseTestCase): 1661 1662 def setUp(self): 1663 super(LogConfigOptsTestCase, self).setUp() 1664 1665 def test_print_help(self): 1666 f = io.StringIO() 1667 self.CONF([]) 1668 self.CONF.print_help(file=f) 1669 for option in ['debug', 'log-config', 'watch-log-file']: 1670 self.assertIn(option, f.getvalue()) 1671 1672 def test_debug(self): 1673 self.CONF(['--debug']) 1674 self.assertEqual(True, self.CONF.debug) 1675 1676 def test_logging_opts(self): 1677 self.CONF([]) 1678 1679 self.assertIsNone(self.CONF.log_config_append) 1680 self.assertIsNone(self.CONF.log_file) 1681 self.assertIsNone(self.CONF.log_dir) 1682 1683 self.assertEqual(_options._DEFAULT_LOG_DATE_FORMAT, 1684 self.CONF.log_date_format) 1685 1686 self.assertEqual(False, self.CONF.use_syslog) 1687 self.assertEqual(False, self.CONF.use_json) 1688 1689 def test_log_file(self): 1690 log_file = '/some/path/foo-bar.log' 1691 self.CONF(['--log-file', log_file]) 1692 self.assertEqual(log_file, self.CONF.log_file) 1693 1694 def test_log_dir_handlers(self): 1695 log_dir = tempfile.mkdtemp() 1696 self.CONF(['--log-dir', log_dir]) 1697 self.CONF.set_default('use_stderr', False) 1698 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1699 logger = log._loggers[None].logger 1700 self.assertEqual(1, len(logger.handlers)) 1701 self.assertIsInstance(logger.handlers[0], 1702 logging.handlers.WatchedFileHandler) 1703 1704 def test_log_publish_errors_handlers(self): 1705 fake_handler = mock.MagicMock() 1706 with mock.patch('oslo_utils.importutils.import_object', 1707 return_value=fake_handler) as mock_import: 1708 log_dir = tempfile.mkdtemp() 1709 self.CONF(['--log-dir', log_dir]) 1710 self.CONF.set_default('use_stderr', False) 1711 self.CONF.set_default('publish_errors', True) 1712 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1713 logger = log._loggers[None].logger 1714 self.assertEqual(2, len(logger.handlers)) 1715 self.assertIsInstance(logger.handlers[0], 1716 logging.handlers.WatchedFileHandler) 1717 self.assertEqual(fake_handler, logger.handlers[1]) 1718 mock_import.assert_called_once_with( 1719 'oslo_messaging.notify.log_handler.PublishErrorsHandler', 1720 logging.ERROR) 1721 1722 def test_logfile_deprecated(self): 1723 logfile = '/some/other/path/foo-bar.log' 1724 self.CONF(['--logfile', logfile]) 1725 self.assertEqual(logfile, self.CONF.log_file) 1726 1727 def test_log_dir(self): 1728 log_dir = '/some/path/' 1729 self.CONF(['--log-dir', log_dir]) 1730 self.assertEqual(log_dir, self.CONF.log_dir) 1731 1732 def test_logdir_deprecated(self): 1733 logdir = '/some/other/path/' 1734 self.CONF(['--logdir', logdir]) 1735 self.assertEqual(logdir, self.CONF.log_dir) 1736 1737 def test_default_formatter(self): 1738 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1739 logger = log._loggers[None].logger 1740 for handler in logger.handlers: 1741 formatter = handler.formatter 1742 self.assertIsInstance(formatter, 1743 formatters.ContextFormatter) 1744 1745 def test_json_formatter(self): 1746 self.CONF(['--use-json']) 1747 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1748 logger = log._loggers[None].logger 1749 for handler in logger.handlers: 1750 formatter = handler.formatter 1751 self.assertIsInstance(formatter, 1752 formatters.JSONFormatter) 1753 1754 def test_handlers_cleanup(self): 1755 """Test that all old handlers get removed from log_root.""" 1756 old_handlers = [log.handlers.ColorHandler(), 1757 log.handlers.ColorHandler()] 1758 log._loggers[None].logger.handlers = list(old_handlers) 1759 log._setup_logging_from_conf(self.CONF, 'test', 'test') 1760 handlers = log._loggers[None].logger.handlers 1761 self.assertEqual(1, len(handlers)) 1762 self.assertNotIn(handlers[0], old_handlers) 1763 1764 def test_list_opts(self): 1765 all_options = _options.list_opts() 1766 (group, options) = all_options[0] 1767 self.assertIsNone(group) 1768 self.assertEqual((_options.common_cli_opts + 1769 _options.logging_cli_opts + 1770 _options.generic_log_opts + 1771 _options.log_opts + 1772 _options.versionutils.deprecated_opts), options) 1773 1774 1775class LogConfigTestCase(BaseTestCase): 1776 def setUp(self): 1777 super(LogConfigTestCase, self).setUp() 1778 names = self.create_tempfiles([('logging', MIN_LOG_INI)]) 1779 self.log_config_append = names[0] 1780 if hasattr(log._load_log_config, 'old_time'): 1781 del log._load_log_config.old_time 1782 1783 def test_log_config_append_ok(self): 1784 self.config(log_config_append=self.log_config_append) 1785 log.setup(self.CONF, 'test_log_config_append') 1786 1787 def test_log_config_append_not_exist(self): 1788 os.remove(self.log_config_append) 1789 self.config(log_config_append=self.log_config_append) 1790 self.assertRaises(log.LogConfigError, log.setup, 1791 self.CONF, 1792 'test_log_config_append') 1793 1794 def test_log_config_append_invalid(self): 1795 names = self.create_tempfiles([('logging', 'squawk')]) 1796 self.log_config_append = names[0] 1797 self.config(log_config_append=self.log_config_append) 1798 self.assertRaises(log.LogConfigError, log.setup, 1799 self.CONF, 1800 'test_log_config_append') 1801 1802 def test_log_config_append_unreadable(self): 1803 os.chmod(self.log_config_append, 0) 1804 self.config(log_config_append=self.log_config_append) 1805 self.assertRaises(log.LogConfigError, log.setup, 1806 self.CONF, 1807 'test_log_config_append') 1808 1809 def test_log_config_append_disable_existing_loggers(self): 1810 self.config(log_config_append=self.log_config_append) 1811 with mock.patch('logging.config.fileConfig') as fileConfig: 1812 log.setup(self.CONF, 'test_log_config_append') 1813 1814 fileConfig.assert_called_once_with(self.log_config_append, 1815 disable_existing_loggers=False) 1816 1817 1818class SavingAdapter(log.KeywordArgumentAdapter): 1819 1820 def __init__(self, *args, **kwds): 1821 super(log.KeywordArgumentAdapter, self).__init__(*args, **kwds) 1822 self.results = [] 1823 1824 def process(self, msg, kwargs): 1825 # Run the real adapter and save the inputs and outputs 1826 # before returning them so the test can examine both. 1827 results = super(SavingAdapter, self).process(msg, kwargs) 1828 self.results.append((msg, kwargs, results)) 1829 return results 1830 1831 1832class KeywordArgumentAdapterTestCase(BaseTestCase): 1833 1834 def setUp(self): 1835 super(KeywordArgumentAdapterTestCase, self).setUp() 1836 # Construct a mock that will look like a Logger configured to 1837 # emit messages at DEBUG or higher. 1838 self.mock_log = mock.Mock() 1839 self.mock_log.manager.disable = logging.NOTSET 1840 self.mock_log.isEnabledFor.return_value = True 1841 self.mock_log.getEffectiveLevel.return_value = logging.DEBUG 1842 1843 def test_empty_kwargs(self): 1844 a = log.KeywordArgumentAdapter(self.mock_log, {}) 1845 msg, kwargs = a.process('message', {}) 1846 self.assertEqual({'extra': {'extra_keys': []}}, kwargs) 1847 1848 def test_include_constructor_extras(self): 1849 key = 'foo' 1850 val = 'blah' 1851 data = {key: val} 1852 a = log.KeywordArgumentAdapter(self.mock_log, data) 1853 msg, kwargs = a.process('message', {}) 1854 self.assertEqual({'extra': {key: val, 'extra_keys': [key]}}, 1855 kwargs) 1856 1857 def test_pass_through_exc_info(self): 1858 a = log.KeywordArgumentAdapter(self.mock_log, {}) 1859 exc_message = 'exception' 1860 msg, kwargs = a.process('message', {'exc_info': exc_message}) 1861 self.assertEqual( 1862 {'extra': {'extra_keys': []}, 1863 'exc_info': exc_message}, 1864 kwargs) 1865 1866 def test_update_extras(self): 1867 a = log.KeywordArgumentAdapter(self.mock_log, {}) 1868 data = {'context': 'some context object', 1869 'instance': 'instance identifier', 1870 'resource_uuid': 'UUID for instance', 1871 'anything': 'goes'} 1872 expected = copy.copy(data) 1873 1874 msg, kwargs = a.process('message', data) 1875 self.assertEqual( 1876 {'extra': {'anything': expected['anything'], 1877 'context': expected['context'], 1878 'extra_keys': sorted(expected.keys()), 1879 'instance': expected['instance'], 1880 'resource_uuid': expected['resource_uuid']}}, 1881 kwargs) 1882 1883 def test_pass_args_to_log(self): 1884 a = SavingAdapter(self.mock_log, {}) 1885 1886 message = 'message' 1887 exc_message = 'exception' 1888 val = 'value' 1889 a.log(logging.DEBUG, message, name=val, exc_info=exc_message) 1890 1891 expected = { 1892 'exc_info': exc_message, 1893 'extra': {'name': val, 'extra_keys': ['name']}, 1894 } 1895 1896 actual = a.results[0] 1897 self.assertEqual(message, actual[0]) 1898 self.assertEqual(expected, actual[1]) 1899 results = actual[2] 1900 self.assertEqual(message, results[0]) 1901 self.assertEqual(expected, results[1]) 1902 1903 def test_pass_args_via_debug(self): 1904 1905 a = SavingAdapter(self.mock_log, {}) 1906 message = 'message' 1907 exc_message = 'exception' 1908 val = 'value' 1909 a.debug(message, name=val, exc_info=exc_message) 1910 1911 expected = { 1912 'exc_info': exc_message, 1913 'extra': {'name': val, 'extra_keys': ['name']}, 1914 } 1915 1916 actual = a.results[0] 1917 self.assertEqual(message, actual[0]) 1918 self.assertEqual(expected, actual[1]) 1919 results = actual[2] 1920 self.assertEqual(message, results[0]) 1921 self.assertEqual(expected, results[1]) 1922 1923 1924class UnicodeConversionTestCase(BaseTestCase): 1925 1926 _MSG = u'Message with unicode char \ua000 in the middle' 1927 1928 def test_ascii_to_unicode(self): 1929 msg = self._MSG 1930 enc_msg = msg.encode('utf-8') 1931 result = formatters._ensure_unicode(enc_msg) 1932 self.assertEqual(msg, result) 1933 self.assertIsInstance(result, str) 1934 1935 def test_unicode_to_unicode(self): 1936 msg = self._MSG 1937 result = formatters._ensure_unicode(msg) 1938 self.assertEqual(msg, result) 1939 self.assertIsInstance(result, str) 1940 1941 def test_exception_to_unicode(self): 1942 msg = self._MSG 1943 exc = Exception(msg) 1944 result = formatters._ensure_unicode(exc) 1945 self.assertEqual(msg, result) 1946 self.assertIsInstance(result, str) 1947 1948 1949class LoggerNameTestCase(LoggerTestCase): 1950 1951 def test_oslo_dot(self): 1952 logger_name = 'oslo.subname' 1953 logger = log.getLogger(logger_name) 1954 self.assertEqual(logger_name, logger.logger.name) 1955 1956 def test_oslo_underscore(self): 1957 logger_name = 'oslo_subname' 1958 expected = logger_name.replace('_', '.') 1959 logger = log.getLogger(logger_name) 1960 self.assertEqual(expected, logger.logger.name) 1961 1962 1963class IsDebugEnabledTestCase(test_base.BaseTestCase): 1964 def setUp(self): 1965 super(IsDebugEnabledTestCase, self).setUp() 1966 self.config_fixture = self.useFixture( 1967 fixture_config.Config(cfg.ConfigOpts())) 1968 self.config = self.config_fixture.config 1969 self.CONF = self.config_fixture.conf 1970 log.register_options(self.config_fixture.conf) 1971 1972 def _test_is_debug_enabled(self, debug=False): 1973 self.config(debug=debug) 1974 self.assertEqual(debug, log.is_debug_enabled(self.CONF)) 1975 1976 def test_is_debug_enabled_off(self): 1977 self._test_is_debug_enabled() 1978 1979 def test_is_debug_enabled_on(self): 1980 self._test_is_debug_enabled(debug=True) 1981