Merge pull request #145 from authorizon/nicer_logging

Increased log verbosity

opal_common/config.py

@@ -4,13 +4,23 @@
 
 from opal_common.authentication.types import EncryptionKeyFormat, JWTAlgorithm
 
+_LOG_FORMAT_WITHOUT_PID = "<green>{time}</green> | <blue>{name: <40}</blue>|<level>{level:^6} | {message}</level>\n{exception}"
+_LOG_FORMAT_WITH_PID = "<green>{time}</green> | {process} | <blue>{name: <40}</blue>|<level>{level:^6} | {message}</level>\n{exception}"
 
 class OpalCommonConfig(Confi):
     ALLOWED_ORIGINS = confi.list("ALLOWED_ORIGINS", ["*"])
     # Process name to show in logs - Not confi-controlable on purpose
     PROCESS_NAME = ""
     # Logging
     # - Log formatting
+    LOG_FORMAT_INCLUDE_PID = confi.bool("LOG_FORMAT_INCLUDE_PID", False)
+    LOG_FORMAT = confi.str(
+        "LOG_FORMAT",
+        confi.delay(
+            lambda LOG_FORMAT_INCLUDE_PID=False:
+            _LOG_FORMAT_WITH_PID if LOG_FORMAT_INCLUDE_PID else _LOG_FORMAT_WITHOUT_PID
+        )
+    )
     LOG_TRACEBACK = confi.bool("LOG_TRACEBACK", True)
     LOG_DIAGNOSE = confi.bool("LOG_DIAGNOSE", True)
     LOG_COLORIZE = confi.bool("LOG_COLORIZE", True)

opal_common/logger.py

@@ -13,12 +13,12 @@ def configure_logs():
     Takeover process logs and create a logger with Loguru according to the configuration
     """
     intercept_handler = InterceptHandler()
-    formatter = Formatter()
+    formatter = Formatter(opal_common_config.LOG_FORMAT)
     filter = ModuleFilter(include_list=opal_common_config.LOG_MODULE_INCLUDE_LIST, exclude_list=opal_common_config.LOG_MODULE_EXCLUDE_LIST)
     logging.basicConfig(handlers=[intercept_handler], level=0, force=True)
     if opal_common_config.LOG_PATCH_UVICORN_LOGS:
         # Monkey patch UVICORN to use our logger
-        hijack_uvicorn_logs()
+        hijack_uvicorn_logs(intercept_handler)
     # Clean slate
     logger.remove()
     # Logger configuration

opal_common/logging/formatter.py

@@ -2,8 +2,9 @@ class Formatter:
 
     MAX_FIELD_LEN = 25
 
-    def __init__(self):
-        self.fmt = "<green>{time}</green> |<blue>{name: <40}</blue>|<level>{level:^6} | {message}</level>\n{exception}"
+    def __init__(self, format_string: str):
+        print(format_string)
+        self.fmt = format_string
 
     def limit_len(self, record, field, length=MAX_FIELD_LEN):
         #Shorten field content

opal_common/logging/thirdparty.py

@@ -1,19 +1,21 @@
-from logging.config import dictConfig
-def hijack_uvicorn_logs():
-    # Intercept future UVICORN
-    from uvicorn.config import LOGGING_CONFIG
-    LOGGING_CONFIG["handlers"] =  {
-            "default": {
-                "formatter": "default",
-                "class": "opal_common.logging.intercept.InterceptHandler",
-            },
-            "access": {
-                "formatter": "access",
-                "class": "opal_common.logging.intercept.InterceptHandler",
-            },
-        }
-    # force existing UVICORN logging
-    dictConfig(LOGGING_CONFIG)
+import logging
 
+def hijack_uvicorn_logs(intercept_handler: logging.Handler):
+    """
+    Uvicorn loggers are configured to use special handlers.
 
+    Adding an intercept handler to the root logger manages to intercept logs from uvicorn, however, the log messages are duplicated.
+    This is happening because uvicorn loggers are propagated by default - we get a log message once for the "uvicorn" / "uvicorn.error"
+    logger and once for the root logger). Another stupid issue is that the "uvicorn.error" logger is not just for errors, which is confusing.
 
+    This method is doing 2 things for each uvicorn logger:
+    1) remove all existing handlers and replace them with the intercept handler (i.e: will be logged via loguru)
+    2) cancel propagation - which will mean messages will not propagate to the root logger (which also has an InterceptHandler), fixing the duplication
+    """
+    # get loggers directly from uvicorn config - if they will change something - we will know.
+    from uvicorn.config import LOGGING_CONFIG
+    uvicorn_logger_names = list(LOGGING_CONFIG.get("loggers", {}).keys()) or ["uvicorn", "uvicorn.access", "uvicorn.error"]
+    for logger_name in uvicorn_logger_names:
+        logger = logging.getLogger(logger_name)
+        logger.handlers = [intercept_handler]
+        logger.propagate = False

requirements.txt

@@ -5,17 +5,17 @@ aiohttp
 broadcaster[postgres]
 colorama
 fastapi==0.65.2
-fastapi_websocket_pubsub>=0.1.18
-fastapi_websocket_rpc>=0.1.18
+fastapi_websocket_pubsub>=0.1.19
+fastapi_websocket_rpc>=0.1.20
 GitPython
 gunicorn
 ipython
 loguru==0.5.3
 psutil==5.8.0
 pydantic[email]
-pyjwt[crypto]
+pyjwt[crypto]==2.1.0
 python-decouple
 tenacity==6.3.1
 typing-extensions
 uvicorn[standard]
-websockets
+websockets==9.1

setup/__version__.py

@@ -7,7 +7,7 @@
 Project homepage: https://github.com/authorizon/opal
 """
 
-VERSION = (0, 1, 14)
+VERSION = (0, 1, 15)
 VERSION_STRING = '.'.join(map(str,VERSION))
 
 __version__ = VERSION_STRING