rework logging for additional context and to include sanic logs

synse_server/api/http.py

@@ -4,10 +4,12 @@
 from sanic import Blueprint
 from sanic.request import Request
 from sanic.response import HTTPResponse, StreamingHTTPResponse, stream
+from structlog import get_logger
 
 from synse_server import cmd, errors, utils
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 # Blueprint for the Synse core (version-less) routes.
 core = Blueprint('core-http')

synse_server/api/websocket.py

@@ -8,12 +8,14 @@
 from sanic import Blueprint
 from sanic.request import Request
 from sanic.websocket import ConnectionClosed, WebSocketCommonProtocol
+from structlog import get_logger
 
 from synse_server import cmd, errors, utils
 from synse_server.i18n import _
-from synse_server.log import logger
 from synse_server.metrics import Monitor
 
+logger = get_logger()
+
 # Blueprint for the Synse v3 WebSocket API.
 v3 = Blueprint('v3-websocket')
 

synse_server/cache.py

@@ -6,11 +6,13 @@
 import aiocache
 import grpc
 import synse_grpc.utils
+from structlog import get_logger
 from synse_grpc import api
 
 from synse_server import config, plugin
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 # The in-memory cache implementation stores data in a class member variable,
 # so all instance of the in memory cache will reference that data structure.

synse_server/cmd/config.py

@@ -1,9 +1,12 @@
 
 from typing import Any, Dict
 
+from structlog import get_logger
+
 from synse_server.config import options
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def config() -> Dict[str, Any]:

synse_server/cmd/info.py

@@ -1,11 +1,13 @@
 
 from typing import Any, Dict
 
+from structlog import get_logger
 from synse_grpc import utils
 
 from synse_server import cache, errors
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def info(device_id: str) -> Dict[str, Any]:

synse_server/cmd/plugin.py

@@ -1,14 +1,16 @@
 
 from typing import Any, Dict, List
 
+from structlog import get_logger
 from synse_grpc import api, utils
 
 import synse_server.utils
 from synse_server import errors
 from synse_server.i18n import _
-from synse_server.log import logger
 from synse_server.plugin import manager
 
+logger = get_logger()
+
 
 async def plugin(plugin_id: str) -> Dict[str, Any]:
     """Generate the plugin response data.

synse_server/cmd/read.py

@@ -6,11 +6,13 @@
 
 import synse_grpc.utils
 import websockets
+from structlog import get_logger
 from synse_grpc import api
 
 from synse_server import cache, errors, plugin
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 def reading_to_dict(reading: api.V3Reading) -> Dict[str, Any]:

synse_server/cmd/scan.py

@@ -1,11 +1,13 @@
 
 from typing import Any, Dict, List
 
+from structlog import get_logger
 from synse_grpc import utils
 
 from synse_server import cache, errors
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def scan(

synse_server/cmd/tags.py

@@ -1,9 +1,12 @@
 
 from typing import List
 
+from structlog import get_logger
+
 from synse_server import cache
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def tags(namespaces: List[str], with_id_tags: bool = False) -> List[str]:

synse_server/cmd/test.py

@@ -1,9 +1,12 @@
 
 from typing import Dict
 
+from structlog import get_logger
+
 from synse_server import utils
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def test() -> Dict[str, str]:

synse_server/cmd/transaction.py

@@ -2,10 +2,12 @@
 from typing import Any, Dict, List
 
 import synse_grpc.utils
+from structlog import get_logger
 
 from synse_server import cache, errors, plugin
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def transaction(transaction_id: str) -> Dict[str, Any]:

synse_server/cmd/version.py

@@ -1,9 +1,12 @@
 
 from typing import Dict
 
+from structlog import get_logger
+
 import synse_server
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def version() -> Dict[str, str]:

synse_server/cmd/write.py

@@ -1,11 +1,13 @@
 
 from typing import Any, Dict, List, Union
 
+from structlog import get_logger
 from synse_grpc import utils
 
 from synse_server import cache, errors
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 async def write_async(device_id: str, payload: Union[Dict, List[Dict]]) -> List[Dict[str, Any]]:

synse_server/discovery/kubernetes.py

@@ -4,10 +4,12 @@
 
 import kubernetes.client
 import kubernetes.config
+from structlog import get_logger
 
 from synse_server import config
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 def discover() -> List[str]:

synse_server/log.py

@@ -5,41 +5,66 @@
 import sys
 
 import structlog
+from sanic import app, asgi, handlers, request, server
 
 from synse_server import config
 
-logging.config.dictConfig({
+logging_config = {
     'version': 1,
     'disable_existing_loggers': False,
     'loggers': {
         'root': {
             'level': 'INFO',
-            'handlers': ['default']
+            'handlers': ['default'],
         },
-        'synse-server': {
+        'synse_server': {
             'level': 'INFO',
-            'handlers': ['default']
+            'handlers': ['default'],
+            'propagate': True,
+        },
+        'sanic.root': {
+            'level': 'INFO',
+            'handlers': ['default'],
+        },
+        'sanic.error': {
+            'level': 'INFO',
+            'handlers': ['error'],
+            'propagate': True,
+            'qualname': 'sanic.error',
+        },
+        'sanic.access': {
+            'level': 'INFO',
+            'handlers': ['default'],
+            'propagate': True,
+            'qualname': 'sanic.access',
         },
     },
     'handlers': {
         'default': {
             'class': 'logging.StreamHandler',
-            'stream': sys.stdout
+            'stream': sys.stdout,
+        },
+        'error': {
+            'class': 'logging.StreamHandler',
+            'stream': sys.stderr,
         },
     },
-})
+}
+
+logging.config.dictConfig(logging_config)
 
 structlog.configure(
     processors=[
         structlog.stdlib.filter_by_level,
+        structlog.stdlib.add_logger_name,
         structlog.stdlib.add_log_level,
         structlog.stdlib.PositionalArgumentsFormatter(),
         structlog.processors.TimeStamper(fmt='iso'),
         structlog.processors.StackInfoRenderer(),
         structlog.processors.format_exc_info,
         structlog.processors.UnicodeDecoder(),
         structlog.processors.KeyValueRenderer(
-            key_order=['timestamp', 'level', 'event']
+            key_order=['timestamp', 'logger', 'level', 'event']
         ),
     ],
     context_class=dict,
@@ -48,10 +73,31 @@
     cache_logger_on_first_use=True,
 )
 
-logger = structlog.get_logger('synse-server')
+
+def override_sanic_loggers():
+    # Override Sanic loggers with structlog loggers. Unfortunately
+    # there isn't a great way of doing this because the Sanic modules
+    # already hold a reference to the logging.Logger at import load,
+    # so we are stuck with just replacing those references in their
+    # respective modules.
+    root = structlog.get_logger('sanic.root')
+    access = structlog.get_logger('sanic.access')
+    error = structlog.get_logger('sanic.error')
+
+    app.error_logger = error
+    app.logger = root
+    asgi.logger = root
+    handlers.logger = root
+    request.logger = root
+    request.error_logger = error
+    server.logger = root
+    server.access_logger = access
+
+
+override_sanic_loggers()
 
 
 def setup_logger() -> None:
     """Configure the Synse Server logger."""
     level = logging.getLevelName(config.options.get('logging', 'info').upper())
-    logger.setLevel(level)
+    structlog.get_logger('synse_server').setLevel(level)

synse_server/plugin.py

@@ -3,14 +3,16 @@
 import time
 from typing import List, Tuple, Union
 
+from structlog import get_logger
 from synse_grpc import client, utils
 
 from synse_server import config
 from synse_server.discovery import kubernetes
 from synse_server.i18n import _
-from synse_server.log import logger
 from synse_server.metrics import MetricsInterceptor
 
+logger = get_logger()
+
 
 class PluginManager:
     """A manager for plugins registered with the Synse Server instance.

synse_server/server.py

@@ -7,10 +7,14 @@
 import os
 import sys
 
+from structlog import get_logger
+
 import synse_server
 from synse_server import app, config, metrics, plugin, tasks
 from synse_server.i18n import _
-from synse_server.log import logger, setup_logger
+from synse_server.log import setup_logger
+
+logger = get_logger()
 
 
 class Synse:
@@ -143,7 +147,6 @@ def run(self) -> None:
         self.app.run(
             host=self.host,
             port=self.port,
-            access_log=False,
             ssl=ssl_context,
         )
 

synse_server/tasks.py

@@ -3,11 +3,13 @@
 import asyncio
 
 import sanic
+from structlog import get_logger
 
 from synse_server import config, plugin
 from synse_server.cache import update_device_cache
 from synse_server.i18n import _
-from synse_server.log import logger
+
+logger = get_logger()
 
 
 def register_with_app(app: sanic.Sanic) -> None:

tests/unit/conftest.py

@@ -20,11 +20,13 @@
 #   @pytest.mark.usefixtures(<FIXTURE NAME>)
 
 
-@pytest.fixture(autouse=True)
+@pytest.fixture(scope='module', autouse=True)
 def disable_loggers():
     """Fixture to disable loggers for the tests."""
 
-    logging.getLogger('synse-server').disabled = True
+    logging.getLogger('synse_server').setLevel(logging.CRITICAL)
+
+    logging.getLogger('synse_server').disabled = True
     logging.getLogger('root').disabled = True
     logging.getLogger('sanic.access').disabled = True
     logging.getLogger('sanic.error').disabled = True