def test_removehandler_removes_handler_if_handler_in_handlers(self):
logger = Logger()
handler = Mock()
logger.handlers = [handler]
logger.remove_handler(handler)
self.assertEqual(logger.handlers, [])
async def test_shutdown_ignores_erros(self):
logger = Logger()
logger.handlers = [
Mock(flush=CoroutineMock(side_effect=ValueError)),
Mock(flush=CoroutineMock()),
]
await logger.shutdown()
logger.handlers[0].close.assert_not_called()
logger.handlers[1].close.assert_called_once()
async def test_shutdown_closes_all_handlers(self):
logger = Logger()
logger.handlers = [
Mock(flush=CoroutineMock()),
Mock(flush=CoroutineMock())
]
await logger.shutdown()
for handler in logger.handlers:
handler.flush.assert_awaited_once()
handler.close.assert_called_once()
def make_logger(config: Mapping[str, Any]) -> Logger:
""" Create Logger instance for using async logging """
handler = AsyncFileHandler(
filename=str(LOGS_PATH.joinpath(f'{config["filename"]}.log')),
encoding='utf-8'
)
logger = Logger(
name=config['name'],
level=config['level'],
)
logger.add_handler(handler)
return logger
async def test_shutdown_doest_not_closes_handlers_twice(self):
handlers = [Mock(flush=CoroutineMock()), Mock(flush=CoroutineMock())]
logger = Logger()
logger.handlers = handlers
await asyncio.gather(logger.shutdown(), logger.shutdown(),
logger.shutdown())
self.assertCountEqual(handlers, logger.handlers)
for handler in logger.handlers:
handler.flush.assert_awaited_once()
handler.close.assert_called_once()
def test_find_caller_without_current_frame_code(self):
logger = Logger()
with patch(
"aiologger.logger.get_current_frame",
return_value=Mock(f_back=object()),
):
caller = logger.find_caller()
self.assertEqual(caller.filename, "(unknown file)")
self.assertEqual(caller.line_number, 0)
self.assertEqual(caller.function_name, "(unknown function)")
self.assertIsNone(caller.stack)
async def test_shutdown_doest_not_closes_handlers_twice(self):
handlers = [Mock(flush=CoroutineMock()), Mock(flush=CoroutineMock())]
logger = Logger(handler_factory=CoroutineMock(return_value=handlers))
await logger._initialize()
await asyncio.gather(logger.shutdown(), logger.shutdown(),
logger.shutdown())
self.assertCountEqual(handlers, logger.handlers)
for handler in logger.handlers:
handler.flush.assert_awaited_once()
handler.close.assert_called_once()
async def test_shutdown_doest_not_closes_handlers_if_not_initialized(self):
initialized_handler = Mock(spec=AsyncStreamHandler)
not_initialized_handler = Mock(spec=AsyncStreamHandler,
initialized=False)
logger = Logger()
logger.handlers = [initialized_handler, not_initialized_handler]
await logger.shutdown()
initialized_handler.flush.assert_awaited_once()
initialized_handler.close.assert_awaited_once()
not_initialized_handler.flush.assert_not_awaited()
not_initialized_handler.close.assert_not_awaited()
async def test_shutdown_closes_all_handlers_if_initialized(self):
handlers = [
Mock(spec=AsyncStreamHandler),
Mock(spec=AsyncStreamHandler),
]
logger = Logger()
logger.handlers = handlers
await logger.shutdown()
self.assertCountEqual(handlers, logger.handlers)
for handler in logger.handlers:
handler.flush.assert_awaited_once()
handler.close.assert_awaited_once()
async def test_init_with_default_handlers_initializes_handlers_with_proper_log_levels(
self):
handlers = [Mock(), Mock()]
with asynctest.patch("aiologger.logger.AsyncStreamHandler",
side_effect=handlers) as init_from_pipe:
logger = Logger.with_default_handlers()
self.assertCountEqual(logger.handlers, handlers)
def test_property_loop_always_return_a_running_loop(self):
logger = Logger(name="mylogger")
# it's not safe to install the loop implictly, callers should use
# asynio.run
with self.assertRaises(RuntimeError):
logger.loop
# it's not safe to run the loop implictly, callers should use
# asynio.run
with contextlib.closing(asyncio.get_event_loop()) as loop:
with self.assertRaises(RuntimeError):
logger.loop
results = []
async def get_logger_loop():
results.append(logger.loop)
loop.run_until_complete(get_logger_loop())
logger_loop, = results
# now that the loop was explicitly set and started, we can use it
self.assertIs(logger_loop, loop)
del logger_loop
self.assertFalse(loop.is_closed())
# now that the loop was explicitly stopped, it's useless to return
loop = asyncio.get_event_loop()
with self.assertRaises(RuntimeError):
logger.loop
async def test_it_only_keeps_a_reference_to_the_loop_after_the_first_log_call(
self):
logger = Logger.with_default_handlers()
self.assertIs(logger._loop, get_running_loop())
await logger.info("Xablau")
self.assertIs(logger._loop, get_running_loop())
async def test_logger_handlers_are_not_initialized_twice(self):
handler = Mock(spec=AsyncStreamHandler, level=logging.DEBUG)
with patch("aiologger.logger.AsyncStreamHandler",
return_value=handler) as Handler:
formatter = Mock()
logger = Logger.with_default_handlers(formatter=formatter)
await asyncio.gather(
logger.info("sardinha"),
logger.info("tilápia"),
logger.info("xerelete"),
logger.error("fraldinha"),
)
Handler.allert_has_calls([
call(
stream=self.write_pipe,
level=logging.DEBUG,
formatter=formatter,
filter=StdoutFilter(),
),
call(
stream=self.write_pipe,
level=logging.WARNING,
formatter=formatter,
),
])
await logger.shutdown()
async def test_it_only_keeps_a_reference_to_the_loop_after_the_first_log_call(
self):
logger = Logger.with_default_handlers()
self.assertIsNone(logger._loop)
await logger.info("Xablau")
self.assertIsInstance(logger._loop, asyncio.AbstractEventLoop)
async def test_it_doesnt_calls_handlers_if_logger_is_disabled(self):
logger = Logger.with_default_handlers()
with asynctest.patch.object(logger, "callHandlers") as callHandlers:
record = Mock()
logger.disabled = True
await logger.handle(record)
callHandlers.assert_not_awaited()
async def test_it_doesnt_calls_handlers_if_record_isnt_loggable(self):
logger = Logger.with_default_handlers()
with patch.object(logger, 'filter', return_value=False) as filter, \
asynctest.patch.object(logger, 'callHandlers') as callHandlers:
record = Mock()
await logger.handle(record)
filter.assert_called_once_with(record)
callHandlers.assert_not_awaited()
def test_property_loop_always_return_a_running_loop(self):
logger = Logger(name="mylogger")
self.assertIsNotNone(logger.loop)
self.assertFalse(logger.loop.is_closed())
logger.loop.close()
asyncio.set_event_loop(asyncio.new_event_loop())
self.assertIsNotNone(logger.loop)
self.assertFalse(logger.loop.is_closed())
async def test_make_log_record_returns_a_log_record(self):
logger = Logger.with_default_handlers()
await logger._initialize()
record = logger.make_log_record(level=10, msg='Xablau', args=None)
self.assertIsInstance(record, LogRecord)
self.assertEqual(record.msg, 'Xablau')
self.assertEqual(record.levelno, 10)
self.assertEqual(record.levelname, 'DEBUG')
async def test_shutdown_doest_not_closes_handlers_if_not_initialized(self):
handler_factory = CoroutineMock(return_value=[
Mock(flush=CoroutineMock()),
Mock(flush=CoroutineMock())
])
logger = Logger(handler_factory=handler_factory)
await logger.shutdown()
handler_factory.assert_not_awaited()
self.assertCountEqual([], logger.handlers)
async def test_it_calls_handlers_if_logger_is_enabled_and_record_is_loggable(
self):
logger = Logger.with_default_handlers()
with patch.object(logger, "filter",
return_value=True) as filter, asynctest.patch.object(
logger, "callHandlers") as callHandlers:
record = Mock()
await logger.handle(record)
filter.assert_called_once_with(record)
callHandlers.assert_awaited_once_with(record)
async def test_it_returns_a_dummy_task_if_logging_isnt_enabled_for_level(
self):
logger = Logger.with_default_handlers()
self.assertIsNone(logger._dummy_task)
with patch.object(logger, "isEnabledFor",
return_value=False) as isEnabledFor, patch.object(
logger, "_dummy_task") as _dummy_task:
log_task = logger.info("im disabled")
isEnabledFor.assert_called_once_with(logging.INFO)
self.assertEqual(log_task, _dummy_task)
async def test_init_with_default_handlers_initializes_handlers_for_stdout_and_stderr(
self):
handlers = [Mock(), Mock()]
with asynctest.patch("aiologger.logger.AsyncStreamHandler",
side_effect=handlers) as handler_init:
logger = Logger.with_default_handlers(loop=self.loop)
self.assertCountEqual(logger.handlers, handlers)
self.assertCountEqual(
[logging.DEBUG, logging.WARNING],
[call[1]["level"] for call in handler_init.call_args_list],
)
async def test_it_returns_a_log_task_if_logging_is_enabled_for_level(self):
logger = Logger.with_default_handlers()
log_task = logger.info("Xablau")
self.assertIsInstance(log_task, asyncio.Task)
self.assertFalse(log_task.done())
await log_task
self.assertTrue(log_task.done())
logged_content = await self.stream_reader.readline()
self.assertEqual(logged_content, b"Xablau\n")
async def test_logger_handlers_are_not_initialized_twice(self):
condition = asyncio.Condition()
initialize_meta = {'count': 0}
async def create_handlers():
async with condition:
await condition.wait_for(
predicate=lambda: initialize_meta['count'] == 4)
return await Logger._create_default_handlers()
handlers_factory = CoroutineMock(side_effect=create_handlers)
logger = Logger(handler_factory=handlers_factory)
original_initialize = logger._initialize
async def initialize():
async with condition:
initialize_meta['count'] += 1
condition.notify_all()
await original_initialize()
patch.object(logger, '_initialize', initialize).start()
await asyncio.gather(
logger.info('sardinha'),
logger.info('tilápia'),
logger.info('xerelete'),
logger.error('fraldinha'),
)
handlers_factory.assert_called_once()
await logger.shutdown()
async def test_init_with_default_handlers_initializes_handlers_for_stdout_and_stderr(
self):
handlers = [Mock(), Mock()]
with asynctest.patch(
'aiologger.logger.AsyncStreamHandler.init_from_pipe',
CoroutineMock(side_effect=handlers)) as init_from_pipe:
logger = Logger.with_default_handlers(loop=self.loop)
await logger._initialize()
self.assertCountEqual(logger.handlers, handlers)
self.assertCountEqual(
[logging.DEBUG, logging.WARNING],
[call[1]['level'] for call in init_from_pipe.await_args_list])
def test_find_caller_without_stack_info(self):
logger = Logger()
def caller_function():
def log_function():
def make_log_task():
return logger.find_caller()
return make_log_task()
return log_function()
caller = caller_function()
self.assertEqual(caller, (__file__, ANY, "caller_function", None))
async def test_log_makes_a_record_with_build_exc_info_from_sys_stack(self):
logger = Logger.with_default_handlers()
try:
raise ValueError("41 isn't the answer")
except Exception as e:
with patch.object(logger, "handle", CoroutineMock()) as handle:
await logger.exception("Xablau")
call = handle.await_args_list.pop()
record: LogRecord = call[0][0]
exc_class, exc, exc_traceback = record.exc_info
self.assertEqual(exc_class, ValueError)
self.assertEqual(exc, e)
async def test_it_raises_an_error_if_no_handlers_are_found_for_record(
self):
logger = Logger.with_default_handlers()
await logger._initialize()
logger.handlers = []
record = LogRecord(level=10,
name='aiologger',
pathname="/aiologger/tests/test_logger.py",
lineno=17,
msg="Xablau!",
exc_info=None,
args=None)
with self.assertRaises(Exception):
await logger.callHandlers(record)
async def test_it_logs_exception_messages(self):
logger = Logger.with_default_handlers()
try:
raise Exception("Xablau")
except Exception:
await logger.exception("Batemos tambores, eles panela.")
logged_content = await self.stream_reader.readline()
self.assertEqual(logged_content, b"Batemos tambores, eles panela.\n")
while self.stream_reader._buffer:
logged_content += await self.stream_reader.readline()
current_func_name = inspect.currentframe().f_code.co_name
self.assertIn(current_func_name.encode(), logged_content)
self.assertIn(b'raise Exception("Xablau")', logged_content)
async def test_callhandlers_calls_handlers_for_loglevel(self):
level10_handler = Mock(level=10, handle=CoroutineMock())
level30_handler = Mock(level=30, handle=CoroutineMock())
logger = Logger.with_default_handlers()
await logger._initialize()
logger.handlers = [level10_handler, level30_handler]
record = LogRecord(level=20,
name='aiologger',
pathname="/aiologger/tests/test_logger.py",
lineno=17,
msg="Xablau!",
exc_info=None,
args=None)
await logger.callHandlers(record)
level10_handler.handle.assert_awaited_once_with(record)
level30_handler.handle.assert_not_awaited()
