# -*- coding: utf-8 -*-
"""
Enhance the default logger, print visual ascii effect for better readability.
"""
import sys
import enum
import logging
import contextlib
from collections.abc import Callable
from functools import wraps
from datetime import datetime, timezone
def create_logger(
name: str | None = None,
level: int = logging.INFO,
log_format: str = "[User %(asctime)s] %(message)s",
datetime_format: str = "%Y-%m-%d %H:%m:%S",
) -> logging.Logger:
logger = logging.getLogger(name)
logger.setLevel(level)
stream_handler = logging.StreamHandler(stream=sys.stdout)
stream_handler.setLevel(level)
formatter = logging.Formatter(
fmt=log_format,
datefmt=datetime_format,
)
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)
logger.parent = None # disable handler from parent logger, only use stream handler
return logger
DEFAULT_TAB = " " * 2
def encode_pipe(pipe: str) -> str:
if len(pipe) == 1:
return pipe + " "
elif len(pipe) == 2 and pipe[1] == " ":
return pipe
else: # pragma: no cover
raise ValueError("the pipe symbol must be one character.")
DEFAULT_PIPE = encode_pipe("| ")
[docs]
class AlignEnum(str, enum.Enum):
"""
Enum for aligning text in ruler. See :func:`format_ruler`.
"""
left = "<"
right = ">"
middle = "^"
[docs]
def decohints(decorator: Callable) -> Callable:
"""
fix pycharm type hint bug for decorator.
"""
return decorator
[docs]
class VisLog:
"""
A logger that supports nested logging.
:param logger: any ``logging.Logger()`` object or any object what support
``logger.debug("message here")``, ``logger.info(...)``, ``logger.warning(...)``,
``logger.error(...)``, ``logger.critical(...)``. The visual logger will
use this object to log the message. If not provided, a new logger will be created.
:param name: a unique name for the logger.
:param level: logging.INFO, logging.DEBUG, logging.WARNING, logging.ERROR, logging.CRITICAL.
:param log_format: the format of the log message, see
https://docs.python.org/3/library/logging.html#formatter-objects
for more information.
:param datetime_format: datetime format for the log message, default is ``%Y-%m-%d %H:%m:%S``
:param tab: the indent string,
:param pipe: the pipe character for nested log block, it has to be single character.
default is "| ".
"""
def __init__(
self,
logger: logging.Logger | None = None,
name: str | None = None,
level: int = logging.INFO,
log_format: str = "[User %(asctime)s] %(message)s",
datetime_format: str = "%Y-%m-%d %H:%m:%S",
tab: str = DEFAULT_TAB,
pipe: str = DEFAULT_PIPE,
):
if logger is None:
self._logger = create_logger(
name=name,
level=level,
log_format=log_format,
datetime_format=datetime_format,
)
else: # pragma: no cover
self._logger = logger
self._handlers = []
# ``_indent`` stores the current level of indentation
self._indent = 0
self._tab = tab
# ``_nest`` stores the current level of nesting
self._nest = 0
# ``_pipes`` is a first in last out stack data structure that stores
# the list of pipe character for different level of nesting
self._pipes = [
pipe,
]
def _pipe_start(
self,
pipe: str | None = None,
) -> str | None:
if pipe is not None:
pipe = encode_pipe(pipe)
current_pipe = self._pipes.pop()
self._pipes.append(pipe)
return current_pipe
else:
return None
def _pipe_end(
self,
pipe: str | None = None,
last_pipe: str | None = None,
):
if pipe is not None:
self._pipes.pop()
self._pipes.append(last_pipe)
[docs]
@contextlib.contextmanager
def pipe(
self,
pipe: str | None = None,
):
"""
Temporarily change the pipe character for nested log block.
Example:
.. code-block:: python
logger.info("a")
with logger.pipe("*"):
logger.info("b")
logger.info("c")
logger.info("d")
The output looks like::
[User] | a
[User] * b
[User] * c
[User] | d
"""
last_pipe = self._pipe_start(pipe)
try:
yield self
finally:
self._pipe_end(pipe, last_pipe)
def _log(
self,
func: Callable,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str:
if tab is None:
tab = self._tab
with self.pipe(pipe=pipe):
lines = msg.split("\n")
for line in lines:
output = format_line(
msg=line,
indent=self._indent + indent,
tab=tab,
nest=self._nest,
_pipes=self._pipes,
)
func(output)
return output
[docs]
def debug(
self,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str: # pragma: no cover
"""
Todo: add docstring
"""
return self._log(
func=self._logger.debug,
msg=msg,
indent=indent,
tab=tab,
pipe=pipe,
)
[docs]
def info(
self,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str:
"""
Todo: add docstring
"""
return self._log(
func=self._logger.info,
msg=msg,
indent=indent,
tab=tab,
pipe=pipe,
)
[docs]
def warning(
self,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str: # pragma: no cover
"""
Todo: add docstring
"""
return self._log(
func=self._logger.warning,
msg=msg,
indent=indent,
tab=tab,
pipe=pipe,
)
[docs]
def error(
self,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str: # pragma: no cover
"""
Todo: add docstring
"""
return self._log(
func=self._logger.error,
msg=msg,
indent=indent,
tab=tab,
pipe=pipe,
)
[docs]
def critical(
self,
msg: str,
indent: int = 0,
tab: str | None = None,
pipe: str | None = None,
) -> str: # pragma: no cover
"""
Todo: add docstring
"""
return self._log(
func=self._logger.critical,
msg=msg,
indent=indent,
tab=tab,
pipe=pipe,
)
[docs]
def ruler(
self,
msg: str,
char: str = "-",
align: AlignEnum = AlignEnum.left,
length: int = 80,
left_padding: int = 5,
right_padding: int = 5,
corner: str = "+",
pipe: str | None = None,
func: Callable | None = None,
) -> str:
"""
Todo: add docstring
"""
if func is None:
func = self._logger.info
with self.pipe(pipe=pipe):
output = format_ruler(
msg,
char,
align,
length,
left_padding,
right_padding,
corner,
self._nest,
self._pipes[:-1],
)
func(output)
return output
def _indent_start(self, level: int = 1):
self._indent += level
def _indent_end(self, level: int = 1):
self._indent -= level
[docs]
@contextlib.contextmanager
def indent(self, level: int = 1):
"""
A context manager that temporarily increase the indentation level.
Example:
.. code-block:: python
logger.ruler("start test indent")
logger.info("a")
with logger.indent():
logger.info("b")
with logger.indent():
logger.info("c")
logger.info("d")
logger.info("e")
logger.ruler("end test indent")
The output looks like::
[User] +----- start test indent -----------------------------------+
[User] | a
[User] | b
[User] | c
[User] | d
[User] | e
[User] +----- end test indent -------------------------------------+
"""
self._indent_start(level=level)
try:
yield self
finally:
self._indent_end(level=level)
def _nested_start(
self,
pipe: str | None = None,
):
self._nest += 1
if pipe is None:
self._pipes.append(DEFAULT_PIPE)
else: # pragma: no cover
self._pipes.append(encode_pipe(pipe))
def _nested_end(self):
self._nest -= 1
self._pipes.pop()
[docs]
@contextlib.contextmanager
def nested(
self,
pipe: str | None = None,
):
"""
A context manager that nest logging for one more level.
Example:
.. code-block:: python
logger.ruler("section 1")
logger.info("hello 1")
with logger.nested():
logger.ruler("section 1.1")
logger.info("hello 1.1")
with logger.nested():
logger.ruler("section 1.1.1")
logger.info("hello 1.1.1")
logger.ruler("section 1.1.1")
logger.ruler("section 1.1")
logger.ruler("section 1")
The output looks like::
[User] +----- section 1 -------------------------------------------+
[User] | hello 1
[User] | +----- section 1.1 ---------------------------------------+
[User] | | hello 1.1
[User] | | +----- section 1.1.1 -----------------------------------+
[User] | | | hello 1.1.1
[User] | | +----- section 1.1.1 -----------------------------------+
[User] | +----- section 1.1 ---------------------------------------+
[User] +----- section 1 -------------------------------------------+
"""
self._nested_start(pipe=pipe)
try:
yield self
finally:
self._nested_end()
[docs]
def pretty_log(
self,
start_msg: str = "Start {func_name}()",
error_msg: str = "Error {func_name}(), elapsed = {elapsed:.2f} sec",
end_msg: str = "End {func_name}(), elapsed = {elapsed:.2f} sec",
char: str = "-",
align: AlignEnum = AlignEnum.left,
length: int = 80,
left_padding: int = 5,
right_padding: int = 5,
corner: str = "+",
nest: int = 0,
pipe: str | None = None,
):
"""
A decorator that pretty print ruler when a function start, error, end.
``start_msg``, ``error_msg`` and ``end_msg`` are string template.
the ``{func_name}`` will become the function you are decorating,
the ``{elapsed}`` will become the execution time of the function.
You can use ``{elapsed:.2f}`` to set the precision to two digits.
The execution time measurement are not accuracy, it is just an estimation
up to three digits precision.
Example:
.. code-block:: python
@nested_logger.pretty_log(nest=1)
def my_func2(name: str):
time.sleep(1)
nested_logger.info(f"{name} do something in my func 2")
@nested_logger.pretty_log()
def my_func1(name: str):
time.sleep(1)
nested_logger.info(f"{name} do something in my func 1")
my_func2(name="bob")
my_func1(name="alice")
The output looks like::
[User] +----- Start my_func1() ------------------------------------+
[User] |
[User] | alice do something in my func 1
[User] | +----- Start my_func2() ----------------------------------+
[User] | |
[User] | | bob do something in my func 2
[User] | |
[User] | +----- End my_func2(), elapsed = 1.00 sec ----------------+
[User] |
[User] +----- End my_func1(), elapsed = 2.00 sec ------------------+
:return: a decorator that you can put on top of your function
"""
@decohints
def deco(func):
@wraps(func)
def wrapper(*args, **kwargs):
st = datetime.now(tz=timezone.utc)
for _ in range(nest):
self._nested_start(pipe=pipe)
if nest == 0 and (pipe is not None):
last_pipe = self._pipe_start(pipe)
self.ruler(
msg=start_msg.format(
func_name=func.__name__,
**kwargs,
),
char=char,
align=align,
length=length,
left_padding=left_padding,
right_padding=right_padding,
corner=corner,
)
self.info("")
try:
result = func(*args, **kwargs)
except Exception as e:
et = datetime.now(tz=timezone.utc)
elapsed = (et - st).total_seconds()
self.info("")
self.ruler(
msg=error_msg.format(
func_name=func.__name__,
elapsed=elapsed,
**kwargs,
),
char=char,
align=align,
length=length,
left_padding=left_padding,
right_padding=right_padding,
corner=corner,
)
for _ in range(nest):
self._nested_end()
if nest == 0 and (pipe is not None):
self._pipe_end(pipe, last_pipe)
raise e
et = datetime.now(tz=timezone.utc)
elapsed = (et - st).total_seconds()
self.info("")
self.ruler(
msg=end_msg.format(
func_name=func.__name__,
elapsed=elapsed,
**kwargs,
),
char=char,
align=align,
length=length,
left_padding=left_padding,
right_padding=right_padding,
corner=corner,
)
for _ in range(nest):
self._nested_end()
if nest == 0 and (pipe is not None):
self._pipe_end(pipe, last_pipe)
return result
return wrapper
return deco
[docs]
def start_and_end(
self,
msg: str,
start_emoji: str = "🟢",
error_emoji: str = "🔴",
end_emoji: str = "🟢",
pipe: str = "| ",
):
"""
A simplified version of the ``pretty_log`` decorator. Visually print
the start and the end of a function.
Example:
.. code-block:: python
@logger.start_and_end(
msg="My Function 1",
start_emoji="🟢",
error_emoji="🔴",
end_emoji="🟢",
pipe="📦",
)
def my_func1(name: str):
time.sleep(1)
logger.info(f"{name} do something in my func 1")
my_func1(name="alice")
The output looks like::
[User] +----- 🕑 🟢 Start 'My Function 1' --------------------------+
[User] 📦
[User] 📦 alice do something in my func 1
[User] 📦
[User] +----- ⏰ 🟢 End 'My Function 1', elapsed = 1.01 sec --------+
:param msg: indicate the name of the function
:param start_emoji: custom emoji for the start message
:param end_emoji: custom emoji for the end message
:param pipe: custom pipe character
:return: a decorator that you can put on top of your function
"""
if start_emoji and (not start_emoji.endswith(" ")):
start_emoji = start_emoji + " "
if error_emoji and (not error_emoji.endswith(" ")):
error_emoji = error_emoji + " "
if end_emoji and (not end_emoji.endswith(" ")):
end_emoji = end_emoji + " "
return self.pretty_log(
start_msg=f"🕑 {start_emoji}Start {msg!r}",
error_msg=f"⏰ {error_emoji}Error {msg!r}, elapsed = {{elapsed:.2f}} sec",
end_msg=f"⏰ {end_emoji}End {msg!r}, elapsed = {{elapsed:.2f}} sec",
pipe=pipe,
)
[docs]
def emoji_block(
self,
msg: str,
emoji: str,
):
"""
A simplified version of the ``start_and_end`` decorator. Use emoji
to Visually print the function logic block
Example:
.. code-block:: python
@logger.emoji_block(
msg="Deploy app {app_name}",
emoji="🚀",
)
def deploy_app(app_name: str):
logger.info("working ...")
logger.info("done")
deploy_app(app_name="my_app")
The output looks like::
[User] +----- 🕑 🚀 Start 'Deploy app my_app' ----------------------+
[User] 🚀
[User] 🚀 working ...
[User] 🚀 done
[User] 🚀
[User] +----- ⏰ ✅ 🚀 End 'Deploy app my_app', elapsed = 1.01 sec -+
:param msg: indicate the name of the function
:param emoji: custom emoji for the visual effect
:return: a decorator that you can put on top of your function
"""
return self.start_and_end(
msg=msg,
start_emoji=emoji,
error_emoji=f"❌ {emoji}",
end_emoji=f"✅ {emoji}",
pipe=emoji,
)
def off(self):
self._handlers = list(self._logger.handlers)
self._logger.handlers.clear()
def on(self):
for handler in self._handlers:
self._logger.handlers.append(handler)
self._handlers.clear()
[docs]
@contextlib.contextmanager
def disabled(
self,
disable: bool = True,
):
"""
Temporarily disable the logger. This is useful when you want to disable
the logger without manually remove the ``logger.debug(...)`` code.
For example, you can use logger in your unit test for debug, and then use
this context manager to disable the logger when you run the test in CI.
Example:
.. code-block:: python
# content of test.py
def _test1():
logger.info(...)
def _test2():
logger.info(...)
def test_all():
with logger.disabled(
disable=True, # this will disable all log
disable=False, # this will show log
):
_test1()
_test2()
.. note::
This method only works when your logger is automatically created by
vislog, or it is a ``logging.Logger``.
"""
try:
if disable:
existing_handlers = list(self._logger.handlers)
self._logger.handlers.clear()
yield self
finally:
if disable:
for handler in existing_handlers:
self._logger.handlers.append(handler)