2020-04-14 10:24:20 -07:00
|
|
|
"""Logging instance setup & configuration."""
|
|
|
|
|
|
|
|
# Standard Library
|
|
|
|
import os
|
2021-01-12 00:16:34 -07:00
|
|
|
import sys
|
2021-09-15 18:25:37 -07:00
|
|
|
import typing as t
|
2020-09-28 14:43:17 -07:00
|
|
|
import logging
|
2020-04-14 10:24:20 -07:00
|
|
|
from datetime import datetime
|
|
|
|
|
|
|
|
# Third Party
|
|
|
|
from loguru import logger as _loguru_logger
|
2021-09-15 18:25:37 -07:00
|
|
|
from gunicorn.glogging import Logger # type: ignore
|
2020-04-14 10:24:20 -07:00
|
|
|
|
2021-01-12 00:16:34 -07:00
|
|
|
_FMT = (
|
2020-04-14 10:24:20 -07:00
|
|
|
"<lvl><b>[{level}]</b> {time:YYYYMMDD} {time:HH:mm:ss} <lw>|</lw> {name}<lw>:</lw>"
|
|
|
|
"<b>{line}</b> <lw>|</lw> {function}</lvl> <lvl><b>→</b></lvl> {message}"
|
|
|
|
)
|
2020-09-28 14:43:17 -07:00
|
|
|
_DATE_FMT = "%Y%m%d %H:%M:%S"
|
|
|
|
_FMT_BASIC = "{message}"
|
2020-04-14 10:24:20 -07:00
|
|
|
_LOG_LEVELS = [
|
2021-04-24 10:44:40 -07:00
|
|
|
{"name": "TRACE", "color": "<m>"},
|
|
|
|
{"name": "DEBUG", "color": "<c>"},
|
|
|
|
{"name": "INFO", "color": "<le>"},
|
|
|
|
{"name": "SUCCESS", "color": "<g>"},
|
|
|
|
{"name": "WARNING", "color": "<y>"},
|
|
|
|
{"name": "ERROR", "color": "<y>"},
|
|
|
|
{"name": "CRITICAL", "color": "<r>"},
|
2020-04-14 10:24:20 -07:00
|
|
|
]
|
|
|
|
|
|
|
|
|
2021-09-15 18:25:37 -07:00
|
|
|
class LibIntercentHandler(logging.Handler):
|
|
|
|
"""Custom log handler for integrating third party library logging with hyperglass's logger."""
|
|
|
|
|
|
|
|
def emit(self, record):
|
|
|
|
"""Emit log record.
|
|
|
|
|
|
|
|
See: https://github.com/Delgan/loguru (Readme)
|
|
|
|
"""
|
|
|
|
# Get corresponding Loguru level if it exists
|
|
|
|
try:
|
|
|
|
level = _loguru_logger.level(record.levelname).name
|
|
|
|
except ValueError:
|
|
|
|
level = record.levelno
|
|
|
|
|
|
|
|
# Find caller from where originated the logged message
|
|
|
|
frame, depth = logging.currentframe(), 2
|
|
|
|
while frame.f_code.co_filename == logging.__file__:
|
|
|
|
frame = frame.f_back
|
|
|
|
depth += 1
|
|
|
|
|
|
|
|
_loguru_logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())
|
|
|
|
|
|
|
|
|
|
|
|
class GunicornLogger(Logger):
|
|
|
|
"""Custom logger to direct Gunicorn/Uvicorn logs to Loguru.
|
|
|
|
|
|
|
|
See: https://pawamoy.github.io/posts/unify-logging-for-a-gunicorn-uvicorn-app/
|
|
|
|
"""
|
|
|
|
|
|
|
|
def setup(self, cfg: t.Any) -> None:
|
|
|
|
"""Override Gunicorn setup."""
|
|
|
|
handler = logging.NullHandler()
|
|
|
|
self.error_logger = logging.getLogger("gunicorn.error")
|
|
|
|
self.error_logger.addHandler(handler)
|
|
|
|
self.access_logger = logging.getLogger("gunicorn.access")
|
|
|
|
self.access_logger.addHandler(handler)
|
|
|
|
self.error_logger.setLevel(cfg.loglevel)
|
|
|
|
self.access_logger.setLevel(cfg.loglevel)
|
|
|
|
|
|
|
|
|
|
|
|
def setup_lib_logging(log_level: str) -> None:
|
|
|
|
"""Override the logging handlers for dependency libraries.
|
|
|
|
|
|
|
|
See: https://pawamoy.github.io/posts/unify-logging-for-a-gunicorn-uvicorn-app/
|
|
|
|
"""
|
|
|
|
|
|
|
|
intercept_handler = LibIntercentHandler()
|
|
|
|
logging.root.setLevel(log_level)
|
|
|
|
|
|
|
|
seen = set()
|
|
|
|
for name in [
|
|
|
|
*logging.root.manager.loggerDict.keys(),
|
2020-10-11 15:39:15 -07:00
|
|
|
"gunicorn",
|
|
|
|
"gunicorn.access",
|
|
|
|
"gunicorn.error",
|
|
|
|
"uvicorn",
|
|
|
|
"uvicorn.access",
|
|
|
|
"uvicorn.error",
|
|
|
|
"uvicorn.asgi",
|
|
|
|
"netmiko",
|
2021-09-15 18:25:37 -07:00
|
|
|
"paramiko",
|
2020-10-11 15:39:15 -07:00
|
|
|
"scrapli",
|
|
|
|
"httpx",
|
2021-09-15 18:25:37 -07:00
|
|
|
]:
|
|
|
|
if name not in seen:
|
|
|
|
seen.add(name.split(".")[0])
|
|
|
|
logging.getLogger(name).handlers = [intercept_handler]
|
|
|
|
|
|
|
|
_loguru_logger.configure(handlers=[{"sink": sys.stdout, "format": _FMT}])
|
2020-10-11 15:39:15 -07:00
|
|
|
|
|
|
|
|
2021-09-12 18:27:10 -07:00
|
|
|
def _log_patcher(record):
|
|
|
|
"""Patch for exception handling in logger.
|
|
|
|
|
|
|
|
See: https://github.com/Delgan/loguru/issues/504
|
|
|
|
"""
|
|
|
|
exception = record["exception"]
|
|
|
|
if exception is not None:
|
|
|
|
fixed = Exception(str(exception.value))
|
|
|
|
record["exception"] = exception._replace(value=fixed)
|
|
|
|
|
|
|
|
|
2021-01-12 00:16:34 -07:00
|
|
|
def base_logger(level: str = "INFO"):
|
2020-04-14 10:24:20 -07:00
|
|
|
"""Initialize hyperglass logging instance."""
|
|
|
|
_loguru_logger.remove()
|
2021-01-12 00:16:34 -07:00
|
|
|
_loguru_logger.add(sys.stdout, format=_FMT, level=level, enqueue=True)
|
2021-09-12 18:27:10 -07:00
|
|
|
_loguru_logger.configure(levels=_LOG_LEVELS, patcher=_log_patcher)
|
2020-04-14 10:24:20 -07:00
|
|
|
return _loguru_logger
|
|
|
|
|
|
|
|
|
|
|
|
log = base_logger()
|
|
|
|
|
2020-09-28 14:43:17 -07:00
|
|
|
logging.addLevelName(25, "SUCCESS")
|
|
|
|
|
|
|
|
|
|
|
|
def _log_success(self, message, *a, **kw):
|
|
|
|
"""Add custom builtin logging handler for the success level."""
|
|
|
|
if self.isEnabledFor(25):
|
|
|
|
self._log(25, message, a, **kw)
|
|
|
|
|
|
|
|
|
|
|
|
logging.Logger.success = _log_success
|
|
|
|
|
2020-04-14 10:24:20 -07:00
|
|
|
|
|
|
|
def set_log_level(logger, debug):
|
|
|
|
"""Set log level based on debug state."""
|
|
|
|
if debug:
|
|
|
|
os.environ["HYPERGLASS_LOG_LEVEL"] = "DEBUG"
|
2021-01-12 00:16:34 -07:00
|
|
|
base_logger("DEBUG")
|
2020-04-14 10:24:20 -07:00
|
|
|
|
|
|
|
if debug:
|
|
|
|
logger.debug("Debugging enabled")
|
|
|
|
return True
|
|
|
|
|
|
|
|
|
|
|
|
def enable_file_logging(logger, log_directory, log_format, log_max_size):
|
|
|
|
"""Set up file-based logging from configuration parameters."""
|
|
|
|
|
|
|
|
if log_format == "json":
|
2020-04-15 11:17:03 -07:00
|
|
|
log_file_name = "hyperglass.log.json"
|
2020-04-14 10:24:20 -07:00
|
|
|
structured = True
|
|
|
|
else:
|
2020-04-15 11:17:03 -07:00
|
|
|
log_file_name = "hyperglass.log"
|
2020-04-14 10:24:20 -07:00
|
|
|
structured = False
|
|
|
|
|
|
|
|
log_file = log_directory / log_file_name
|
|
|
|
|
|
|
|
if log_format == "text":
|
|
|
|
now_str = "hyperglass logs for " + datetime.utcnow().strftime(
|
|
|
|
"%B %d, %Y beginning at %H:%M:%S UTC"
|
|
|
|
)
|
|
|
|
now_str_y = len(now_str) + 6
|
|
|
|
now_str_x = len(now_str) + 4
|
|
|
|
log_break = (
|
|
|
|
"#" * now_str_y,
|
|
|
|
"\n#" + " " * now_str_x + "#\n",
|
|
|
|
"# ",
|
|
|
|
now_str,
|
|
|
|
" #",
|
|
|
|
"\n#" + " " * now_str_x + "#\n",
|
|
|
|
"#" * now_str_y,
|
|
|
|
)
|
|
|
|
|
|
|
|
with log_file.open("a+") as lf:
|
|
|
|
lf.write(f'\n\n{"".join(log_break)}\n\n')
|
|
|
|
|
2020-09-28 14:43:17 -07:00
|
|
|
logger.add(
|
2021-09-12 15:09:24 -07:00
|
|
|
log_file, format=_FMT, rotation=log_max_size, serialize=structured, enqueue=True,
|
2020-09-28 14:43:17 -07:00
|
|
|
)
|
2020-04-14 10:24:20 -07:00
|
|
|
|
2020-09-28 14:43:17 -07:00
|
|
|
logger.debug("Logging to {} enabled", str(log_file))
|
2020-04-14 10:24:20 -07:00
|
|
|
|
|
|
|
return True
|
|
|
|
|
|
|
|
|
|
|
|
def enable_syslog_logging(logger, syslog_host, syslog_port):
|
|
|
|
"""Set up syslog logging from configuration parameters."""
|
2020-09-28 14:43:17 -07:00
|
|
|
|
|
|
|
# Standard Library
|
2020-04-14 10:24:20 -07:00
|
|
|
from logging.handlers import SysLogHandler
|
|
|
|
|
|
|
|
logger.add(
|
2021-09-12 15:09:24 -07:00
|
|
|
SysLogHandler(address=(str(syslog_host), syslog_port)), format=_FMT_BASIC, enqueue=True,
|
2020-04-14 10:24:20 -07:00
|
|
|
)
|
|
|
|
logger.debug(
|
2020-09-28 14:43:17 -07:00
|
|
|
"Logging to syslog target {}:{} enabled", str(syslog_host), str(syslog_port),
|
2020-04-14 10:24:20 -07:00
|
|
|
)
|
|
|
|
return True
|