From 59d49261a98d558ffec4df36e4e792212b2a5363 Mon Sep 17 00:00:00 2001 From: Erick Daniszewski Date: Wed, 29 Jan 2020 23:30:16 -0500 Subject: [PATCH] rework logging for additional context and to include sanic logs --- synse_server/api/http.py | 4 +- synse_server/api/websocket.py | 4 +- synse_server/cache.py | 4 +- synse_server/cmd/config.py | 5 ++- synse_server/cmd/info.py | 4 +- synse_server/cmd/plugin.py | 4 +- synse_server/cmd/read.py | 4 +- synse_server/cmd/scan.py | 4 +- synse_server/cmd/tags.py | 5 ++- synse_server/cmd/test.py | 5 ++- synse_server/cmd/transaction.py | 4 +- synse_server/cmd/version.py | 5 ++- synse_server/cmd/write.py | 4 +- synse_server/discovery/kubernetes.py | 4 +- synse_server/log.py | 64 ++++++++++++++++++++++++---- synse_server/plugin.py | 4 +- synse_server/server.py | 7 ++- synse_server/tasks.py | 4 +- tests/unit/conftest.py | 6 ++- tests/unit/test_log.py | 9 ++-- tests/unit/test_server.py | 3 -- 21 files changed, 122 insertions(+), 35 deletions(-) diff --git a/synse_server/api/http.py b/synse_server/api/http.py index 94ed52d8..8d5a7656 100644 --- a/synse_server/api/http.py +++ b/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') diff --git a/synse_server/api/websocket.py b/synse_server/api/websocket.py index 9f80c497..5d368b08 100644 --- a/synse_server/api/websocket.py +++ b/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') diff --git a/synse_server/cache.py b/synse_server/cache.py index 16f93bb0..7964aae7 100644 --- a/synse_server/cache.py +++ b/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. diff --git a/synse_server/cmd/config.py b/synse_server/cmd/config.py index c1b01c90..e1c67392 100644 --- a/synse_server/cmd/config.py +++ b/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]: diff --git a/synse_server/cmd/info.py b/synse_server/cmd/info.py index 1c6662a4..52b6b724 100644 --- a/synse_server/cmd/info.py +++ b/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]: diff --git a/synse_server/cmd/plugin.py b/synse_server/cmd/plugin.py index fb3ffad6..40483e13 100644 --- a/synse_server/cmd/plugin.py +++ b/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. diff --git a/synse_server/cmd/read.py b/synse_server/cmd/read.py index 8640d85e..7f36d6f8 100644 --- a/synse_server/cmd/read.py +++ b/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]: diff --git a/synse_server/cmd/scan.py b/synse_server/cmd/scan.py index c831415c..dbda163b 100644 --- a/synse_server/cmd/scan.py +++ b/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( diff --git a/synse_server/cmd/tags.py b/synse_server/cmd/tags.py index b6730b71..ffbabe30 100644 --- a/synse_server/cmd/tags.py +++ b/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]: diff --git a/synse_server/cmd/test.py b/synse_server/cmd/test.py index 36868f89..4051ae94 100644 --- a/synse_server/cmd/test.py +++ b/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]: diff --git a/synse_server/cmd/transaction.py b/synse_server/cmd/transaction.py index f1893220..bdc70eb8 100644 --- a/synse_server/cmd/transaction.py +++ b/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]: diff --git a/synse_server/cmd/version.py b/synse_server/cmd/version.py index 1a9bf427..92b8bdd8 100644 --- a/synse_server/cmd/version.py +++ b/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]: diff --git a/synse_server/cmd/write.py b/synse_server/cmd/write.py index 3f7a602c..ecf64733 100644 --- a/synse_server/cmd/write.py +++ b/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]]: diff --git a/synse_server/discovery/kubernetes.py b/synse_server/discovery/kubernetes.py index 66f1f50b..f6110040 100644 --- a/synse_server/discovery/kubernetes.py +++ b/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]: diff --git a/synse_server/log.py b/synse_server/log.py index dc0a5e64..d61f3e41 100644 --- a/synse_server/log.py +++ b/synse_server/log.py @@ -5,33 +5,58 @@ 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'), @@ -39,7 +64,7 @@ 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) diff --git a/synse_server/plugin.py b/synse_server/plugin.py index 02d32531..cacb3650 100644 --- a/synse_server/plugin.py +++ b/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. diff --git a/synse_server/server.py b/synse_server/server.py index 4f76f352..90febd95 100644 --- a/synse_server/server.py +++ b/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, ) diff --git a/synse_server/tasks.py b/synse_server/tasks.py index 00131d3f..c6411aea 100644 --- a/synse_server/tasks.py +++ b/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: diff --git a/tests/unit/conftest.py b/tests/unit/conftest.py index cac09360..e162b5fd 100644 --- a/tests/unit/conftest.py +++ b/tests/unit/conftest.py @@ -20,11 +20,13 @@ # @pytest.mark.usefixtures() -@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 diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index 90a0492f..e97735a9 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -1,14 +1,17 @@ import logging +import structlog + from synse_server import log def test_setup_logger_defaults(): - log.logger.setLevel(logging.DEBUG) + logger = structlog.get_logger('synse_server') + logger.setLevel(logging.DEBUG) log.setup_logger() - assert log.logger.getEffectiveLevel() == logging.INFO + assert logger.getEffectiveLevel() == logging.INFO def test_setup_logger_configured(mocker): @@ -17,7 +20,7 @@ def test_setup_logger_configured(mocker): # --- Test case ----------------------------- log.setup_logger() - assert log.logger.getEffectiveLevel() == logging.ERROR + assert structlog.get_logger('synse_server').getEffectiveLevel() == logging.ERROR mock_get.assert_called_once() mock_get.assert_called_with('logging', 'info') diff --git a/tests/unit/test_server.py b/tests/unit/test_server.py index 2120d7a0..df9166e1 100644 --- a/tests/unit/test_server.py +++ b/tests/unit/test_server.py @@ -75,7 +75,6 @@ def test_run_ok_with_metrics(self, mocker): mock_run.assert_called_with( host='0.0.0.0', port=5000, - access_log=False, ssl=None, ) @@ -105,7 +104,6 @@ def test_run_ok_with_ssl(self, mocker): mock_run.assert_called_with( host='0.0.0.0', port=5000, - access_log=False, ssl={ 'cert': 'test-cert', 'key': 'test-key', @@ -139,7 +137,6 @@ def test_run_error(self, mocker): mock_run.assert_called_with( host='0.0.0.0', port=5000, - access_log=False, ssl={ 'cert': 'test-cert', 'key': 'test-key',