From b595499a796535eaa716cb7c0f70c29db141cb18 Mon Sep 17 00:00:00 2001 From: madkote Date: Mon, 27 Sep 2021 11:13:24 +0200 Subject: [PATCH] logging pluging and middleware helper --- CHANGES.md | 3 + Dockerfile | 2 +- README.md | 26 +- alt_requirements/requirements_full.txt | 1 + alt_requirements/requirements_logger.txt | 2 + demo.py | 122 ++++++- docker-compose.yml | 3 + docs/cache.md | 4 +- docs/control.md | 4 +- docs/logger.md | 170 ++++++++++ docs/scheduler.md | 2 +- docs/settings.md | 2 +- fastapi_plugins/__init__.py | 19 +- fastapi_plugins/_redis.py | 4 +- fastapi_plugins/logger.py | 257 ++++++++++++++ fastapi_plugins/memcached.py | 4 +- fastapi_plugins/middleware.py | 47 +++ fastapi_plugins/plugin.py | 4 +- fastapi_plugins/scheduler.py | 4 +- fastapi_plugins/version.py | 6 +- scripts/demo_app.py | 25 +- setup.py | 7 +- tests/conftest.py | 7 +- tests/test_control.py | 10 +- tests/test_logger.py | 412 +++++++++++++++++++++++ tests/test_memcached.py | 17 +- tests/test_redis.py | 30 +- tests/test_scheduler.py | 8 +- tests/test_settings.py | 8 +- 29 files changed, 1121 insertions(+), 89 deletions(-) create mode 100644 alt_requirements/requirements_logger.txt create mode 100644 docs/logger.md create mode 100644 fastapi_plugins/logger.py create mode 100644 fastapi_plugins/middleware.py create mode 100644 tests/test_logger.py diff --git a/CHANGES.md b/CHANGES.md index 1fdb13f..2253b43 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,4 +1,7 @@ # Changes +## 0.9.0 (2021-09-27) +- `[feature]` Logging plugin +- `[feature]` Middleware interface - register middleware at application ## 0.8.2 (2021-09-23) - `[fix]` Fix dependency for aioredis ## 0.8.1 (2021-03-31) diff --git a/Dockerfile b/Dockerfile index 0515582..4e6fa52 100644 --- a/Dockerfile +++ b/Dockerfile @@ -1,7 +1,7 @@ FROM python:3.8-alpine as demo LABEL maintainer="madkote(at)bluewin.ch" RUN apk --update add --no-cache --virtual MY_DEV_PACK alpine-sdk build-base python3-dev -RUN pip3 install fastapi-plugins uvicorn +RUN pip3 install fastapi-plugins[all] uvicorn RUN mkdir -p /usr/src/app COPY ./scripts/demo_app.py /usr/src/app WORKDIR /usr/src/app diff --git a/README.md b/README.md index fb9ddf9..a20fd96 100644 --- a/README.md +++ b/README.md @@ -31,6 +31,7 @@ The concept is `plugin` - plug a functional utility into your application withou * [Health](./docs/control.md#health) * [Heartbeat](./docs/control.md#heartbeat) * [Application settings/configuration](./docs/settings.md) +* [Logging](./docs/logger.md) * Celery * MQ * and much more is already in progress... @@ -43,6 +44,7 @@ See [release notes](CHANGES.md) * [Redis](./docs/cache.md#redis) * [Scheduler](./docs/scheduler.md) * [Control](./docs/control.md) + * [Logging](./docs/logger.md) * `memcached` adds [Memcached](#memcached) * `all` add everything above @@ -72,15 +74,19 @@ from fastapi_plugins.memcached import memcached_plugin import asyncio import aiojobs import aioredis +import logging @fastapi_plugins.registered_configuration class AppSettings( fastapi_plugins.ControlSettings, fastapi_plugins.RedisSettings, fastapi_plugins.SchedulerSettings, + fastapi_plugins.LoggingSettings, MemcachedSettings, ): api_name: str = str(__name__) + logging_level: int = logging.DEBUG + logging_style: fastapi_plugins.LoggingStyle = fastapi_plugins.LoggingStyle.logjson @fastapi_plugins.registered_configuration(name='sentinel') @@ -89,15 +95,18 @@ class AppSettingsSentinel(AppSettings): redis_sentinels = 'localhost:26379' -app = fastapi.FastAPI() +app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.get_config() @app.get("/") async def root_get( cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), - conf: pydantic.BaseSettings=fastapi.Depends(fastapi_plugins.depends_config) # noqa E501 + conf: pydantic.BaseSettings=fastapi.Depends(fastapi_plugins.depends_config), # noqa E501 + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging) ) -> typing.Dict: - return dict(ping=await cache.ping(), api_name=conf.api_name) + ping = await cache.ping() + logger.debug('root_get', extra=dict(ping=ping, api_name=conf.api_name)) + return dict(ping=ping, api_name=conf.api_name) @app.post("/jobs/schedule/") @@ -105,22 +114,30 @@ async def job_post( timeout: int=fastapi.Query(..., title='the job sleep time'), cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), scheduler: aiojobs.Scheduler=fastapi.Depends(fastapi_plugins.depends_scheduler), # noqa E501 + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging) ) -> str: async def coro(job_id, timeout, cache): await cache.set(job_id, 'processing') try: await asyncio.sleep(timeout) if timeout == 8: + logger.critical('Ugly erred job %s' % job_id) raise Exception('ugly error') except asyncio.CancelledError: await cache.set(job_id, 'canceled') + logger.warning('Cancel job %s' % job_id) except Exception: await cache.set(job_id, 'erred') + logger.error('Erred job %s' % job_id) else: await cache.set(job_id, 'success') + logger.info('Done job %s' % job_id) job_id = str(uuid.uuid4()).replace('-', '') + logger = await fastapi_plugins.log_adapter(logger, extra=dict(job_id=job_id, timeout=timeout)) # noqa E501 + logger.info('New job %s' % job_id) await cache.set(job_id, 'pending') + logger.debug('Pending job %s' % job_id) await scheduler.spawn(coro(job_id, timeout, cache)) return job_id @@ -153,6 +170,8 @@ async def memcached_demo_post( async def on_startup() -> None: await fastapi_plugins.config_plugin.init_app(app, config) await fastapi_plugins.config_plugin.init() + await fastapi_plugins.log_plugin.init_app(app, config, name=__name__) + await fastapi_plugins.log_plugin.init() await memcached_plugin.init_app(app, config) await memcached_plugin.init() await fastapi_plugins.redis_plugin.init_app(app, config=config) @@ -174,6 +193,7 @@ async def on_shutdown() -> None: await fastapi_plugins.scheduler_plugin.terminate() await fastapi_plugins.redis_plugin.terminate() await memcached_plugin.terminate() + await fastapi_plugins.log_plugin.terminate() await fastapi_plugins.config_plugin.terminate() ``` diff --git a/alt_requirements/requirements_full.txt b/alt_requirements/requirements_full.txt index a7d368d..4084bb5 100644 --- a/alt_requirements/requirements_full.txt +++ b/alt_requirements/requirements_full.txt @@ -1,4 +1,5 @@ -r requirements_core.txt -r requirements_jobs.txt +-r requirements_logger.txt -r requirements_memcached.txt -r requirements_redis.txt \ No newline at end of file diff --git a/alt_requirements/requirements_logger.txt b/alt_requirements/requirements_logger.txt new file mode 100644 index 0000000..a908b71 --- /dev/null +++ b/alt_requirements/requirements_logger.txt @@ -0,0 +1,2 @@ +-r requirements_core.txt +python-json-logger>=2.0.* diff --git a/demo.py b/demo.py index 64caaae..8d81248 100644 --- a/demo.py +++ b/demo.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2019, madkote +:copyright: Copyright 2021, madkote demo ---- @@ -14,6 +14,7 @@ from __future__ import absolute_import import asyncio +import logging import os import time @@ -22,12 +23,10 @@ import fastapi_plugins -VERSION = (1, 0, 0) - __all__ = [] __author__ = 'madkote ' -__version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2019, madkote' +__version__ = '.'.join(str(x) for x in fastapi_plugins.VERSION) +__copyright__ = 'Copyright 2021, madkote' class OtherSettings(pydantic.BaseSettings): @@ -36,15 +35,17 @@ class OtherSettings(pydantic.BaseSettings): class AppSettings( OtherSettings, + fastapi_plugins.LoggingSettings, fastapi_plugins.RedisSettings, fastapi_plugins.SchedulerSettings ): api_name: str = str(__name__) + logging_level: int = logging.INFO async def test_redis(): print('--- do redis test') - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings() config = None config = AppSettings(redis_host='127.0.0.1') @@ -71,7 +72,7 @@ async def coro(name, timeout): raise e print('--- do schedule test') - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.SchedulerSettings() config = None config = AppSettings(aiojobs_limit=100) @@ -146,9 +147,11 @@ async def coro(con, name, timeout): raise e print('--- do demo') - app = fastapi.FastAPI() - config = AppSettings() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = AppSettings(logging_style=fastapi_plugins.LoggingStyle.logfmt) + await fastapi_plugins.log_plugin.init_app(app, config, name=__name__) + await fastapi_plugins.log_plugin.init() await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() await fastapi_plugins.scheduler_plugin.init_app(app=app, config=config) @@ -159,20 +162,104 @@ async def coro(con, name, timeout): num_sleep = 0.25 print('- play') + l = await fastapi_plugins.log_plugin() c = await fastapi_plugins.redis_plugin() s = await fastapi_plugins.scheduler_plugin() for i in range(num_jobs): await s.spawn(coro(c, str(i), i/10)) - print('- sleep', num_sleep) + l.info('- sleep %s' % num_sleep) + # print('- sleep', num_sleep) await asyncio.sleep(num_sleep) - print('- check') + l.info('- check') + # print('- check') for i in range(num_jobs): - print(i, '==', await c.get(str(i))) + l.info('%s == %s' % (i, await c.get(str(i)))) + # print(i, '==', await c.get(str(i))) finally: print('- terminate') await fastapi_plugins.scheduler_plugin.terminate() await fastapi_plugins.redis_plugin.terminate() - print('---test schedule done') + await fastapi_plugins.log_plugin.terminate() + print('---demo done') + + +async def test_demo_custom_log(): + async def coro(con, name, timeout): + try: + await con.set(name, '...') + print('> sleep', name, timeout) + await asyncio.sleep(timeout) + await con.set(name, 'done') + print('---> sleep done', name, timeout) + except asyncio.CancelledError as e: + print('coro cancelled', name) + raise e + + class CustomLoggingSettings(fastapi_plugins.LoggingSettings): + another_format: str = '%(asctime)s %(levelname)-8s %(name)-15s %(message)s' + + class CustomLoggingPlugin(fastapi_plugins.LoggingPlugin): + def _create_logger( + self, + name:str, + config:pydantic.BaseSettings=None + ) -> logging.Logger: + import sys + handler = logging.StreamHandler(stream=sys.stderr) + formatter = logging.Formatter(config.another_format) + logger = logging.getLogger(name) + # + logger.setLevel(config.logging_level) + handler.setLevel(config.logging_level) + handler.setFormatter(formatter) + logger.addHandler(handler) + return logger + + class AppSettings( + OtherSettings, + fastapi_plugins.RedisSettings, + fastapi_plugins.SchedulerSettings, + CustomLoggingSettings + ): + api_name: str = str(__name__) + logging_level: int = logging.INFO + + print('--- do demo') + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = AppSettings(logging_style=fastapi_plugins.LoggingStyle.logfmt) + mylog_plugin = CustomLoggingPlugin() + + await mylog_plugin.init_app(app, config, name=__name__) + await mylog_plugin.init() + await fastapi_plugins.redis_plugin.init_app(app=app, config=config) + await fastapi_plugins.redis_plugin.init() + await fastapi_plugins.scheduler_plugin.init_app(app=app, config=config) + await fastapi_plugins.scheduler_plugin.init() + + try: + num_jobs = 10 + num_sleep = 0.25 + + print('- play') + l = await mylog_plugin() + c = await fastapi_plugins.redis_plugin() + s = await fastapi_plugins.scheduler_plugin() + for i in range(num_jobs): + await s.spawn(coro(c, str(i), i/10)) + l.info('- sleep %s' % num_sleep) + # print('- sleep', num_sleep) + await asyncio.sleep(num_sleep) + l.info('- check') + # print('- check') + for i in range(num_jobs): + l.info('%s == %s' % (i, await c.get(str(i)))) + # print(i, '==', await c.get(str(i))) + finally: + print('- terminate') + await fastapi_plugins.scheduler_plugin.terminate() + await fastapi_plugins.redis_plugin.terminate() + await mylog_plugin.terminate() + print('---demo done') async def test_memcached(): @@ -184,7 +271,7 @@ class MoreSettings(AppSettings, MemcachedSettings): memcached_prestart_tries = 5 memcached_prestart_wait = 1 - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = MoreSettings() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() @@ -228,11 +315,18 @@ def main_demo(): loop = asyncio.get_event_loop() loop.run_until_complete(test_demo()) +def main_demo_custom_log(): + print(os.linesep * 3) + print('=' * 50) + loop = asyncio.get_event_loop() + loop.run_until_complete(test_demo_custom_log()) + if __name__ == '__main__': main_redis() main_scheduler() main_demo() + main_demo_custom_log() # try: main_memcached() diff --git a/docker-compose.yml b/docker-compose.yml index 94d8576..dff3fec 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -5,6 +5,9 @@ services: environment: - REDIS_TYPE=redis - REDIS_HOST=redis + - LOGGING_LEVEL=10 # 0, 10, 20, 30, 40, 50 + - LOGGING_STYLE=json # txt, json, logfmt + - LOGGING_FMT= # "%(asctime)s %(levelname) %(message)s" ports: - "8000:8000" build: diff --git a/docs/cache.md b/docs/cache.md index fa31bda..2d15e0a 100644 --- a/docs/cache.md +++ b/docs/cache.md @@ -23,7 +23,7 @@ Valid variable are class AppSettings(OtherSettings, MemcachedSettings): api_name: str = str(__name__) - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = AppSettings() @app.get("/") @@ -81,7 +81,7 @@ Valid variable are class AppSettings(OtherSettings, fastapi_plugins.RedisSettings): api_name: str = str(__name__) - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = AppSettings() @app.get("/") diff --git a/docs/control.md b/docs/control.md index 5ba3209..8794851 100644 --- a/docs/control.md +++ b/docs/control.md @@ -50,7 +50,7 @@ exception. return dict(myinfo='OK', mytype='counter health') myplugin = MyPluginWithHealth() - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = AppSettings() @app.get("/") @@ -98,7 +98,7 @@ The endpoint `/control/heartbeat` returns heart beat of the application - simple # control_enable_heartbeat: bool = True # control_enable_version: bool = True - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = AppSettings() @app.get("/") diff --git a/docs/logger.md b/docs/logger.md new file mode 100644 index 0000000..f903c79 --- /dev/null +++ b/docs/logger.md @@ -0,0 +1,170 @@ +# Logging +## Supported formats +* Default +* JSON +* Logfmt + +Shipped plugin will dump all logs to `sys.stdout`. In order to change/add more handlers or +formats, override the plugin and implement missing functionality (you also can provide PR). +For details see below. + +## Valid variables and values +* `LOGGING_LEVEL` - verbosity level + * any valid level provided by standard `logging` library (e.g. `10`, `20`, `30`, ...) +* `LOGGING_STYLE` - style/format of log records + * `txt` - default `logging` format + * `json` - JSON format + * `logfmt` - `Logfmt` format (key, value) +* `LOGGING_HANDLER` - Handler type for log entries. + * `stdout` - Output log entries to `sys.stdout`. + * `list` - Collect log entries in a queue, **for testing purposes only**. +* `LOGGING_FMT` - logging format for default formatter, e.g. `"%(asctime)s %(levelname) %(message)s"`. + **Note**: this parameter is only valid in conjuction with `LOGGING_STYLE=txt`. + +## Example +### Application +```python + # run with `uvicorn demo_app:app` + import logging + import typing + import aioredis + import fastapi + import pydantic + import fastapi_plugins + + class AppSettings(OtherSettings, fastapi_plugins.LoggingSettings, fastapi_plugins.RedisSettings): + api_name: str = str(__name__) + logging_level: int = logging.DEBUG + logging_style: fastapi_plugins.LoggingStyle = fastapi_plugins.LoggingStyle.logjson + + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = AppSettings() + + @app.get("/") + async def root_get( + cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging), + ) -> typing.Dict: + ping = await cache.ping() + logger.debug('root_get', extra=dict(ping=ping)) + return dict(ping=ping) + + @app.on_event('startup') + async def on_startup() -> None: + await fastapi_plugins.log_plugin.init_app(app, config=config, name=__name__) + await fastapi_plugins.log_plugin.init() + await fastapi_plugins.redis_plugin.init_app(app, config=config) + await fastapi_plugins.redis_plugin.init() + + @app.on_event('shutdown') + async def on_shutdown() -> None: + await fastapi_plugins.redis_plugin.terminate() + await fastapi_plugins.log_plugin.terminate() +``` + +### Application with Logging Adapter +```python + ... as above ... + + @app.post("/jobs/schedule/") + async def job_post( + cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging) + ) -> str: + async def coro(job_id, cache): + logger.info('Done job %s' % job_id) + + # create a job ID + job_id = str(uuid.uuid4()).replace('-', '') + + # create logging adapter which will contain job ID in every log record + logger = await fastapi_plugins.log_adapter( + logger, + extra=dict(job_id=job_id, other='some static information') + ) + + # job_id and other will be now part of log record + logger.info('New job %s' % job_id) + await cache.set(job_id, 'pending') + logger.debug('Pending job %s' % job_id) + # await scheduler.spawn(coro(job_id, cache)) + return job_id +``` + +### Custom formats and handlers +```python + # run with `uvicorn demo_app:app` + import logging + import typing + import aioredis + import fastapi + import pydantic + import fastapi_plugins + + class CustomLoggingSettings(fastapi_plugins.LoggingSettings): + some_settings: ... = ... + + class CustomLoggingPlugin(fastapi_plugins.LoggingPlugin): + def _create_logger( + self, + name:str, + config:pydantic.BaseSettings=None + ) -> logging.Logger: + import sys + handler = logging.StreamHandler(stream=sys.stderr) + formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(name)-15s %(message)s') + logger = logging.getLogger(name) + # + logger.setLevel(config.logging_level) + handler.setLevel(config.logging_level) + handler.setFormatter(formatter) + logger.addHandler(handler) + return logger + + class AppSettings(OtherSettings, CustomLoggingSettings, fastapi_plugins.RedisSettings): + api_name: str = str(__name__) + logging_level: int = logging.DEBUG + + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = AppSettings() + fastapi_plugins.log_plugin = CustomLoggingPlugin() + + @app.get("/") + async def root_get( + cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging), + ) -> typing.Dict: + ping = await cache.ping() + logger.debug('root_get', extra=dict(ping=ping)) + return dict(ping=ping) + + @app.on_event('startup') + async def on_startup() -> None: + await fastapi_plugins.log_plugin.init_app(app, config, name=__name__) + await fastapi_plugins.log_plugin.init() + await fastapi_plugins.redis_plugin.init_app(app, config=config) + await fastapi_plugins.redis_plugin.init() + + @app.on_event('shutdown') + async def on_shutdown() -> None: + await fastapi_plugins.redis_plugin.terminate() + await fastapi_plugins.log_plugin.terminate() +``` + +### Docker Compose +```YAML +version: '3.7' +services: + redis: + image: redis + ports: + - "6379:6379" + demo_fastapi_plugin: + image: demo_fastapi_plugin + environment: + - LOGGING_LEVEL=10 # 0, 10, 20, 30, 40, 50 + - LOGGING_STYLE=json # txt, json, logfmt + - ... + ports: + - "8000:8000" +``` diff --git a/docs/scheduler.md b/docs/scheduler.md index 85f282f..7b9446b 100644 --- a/docs/scheduler.md +++ b/docs/scheduler.md @@ -17,7 +17,7 @@ import fastapi_plugins class AppSettings(OtherSettings, fastapi_plugins.RedisSettings, fastapi_plugins.SchedulerSettings): api_name: str = str(__name__) -app = fastapi.FastAPI() +app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = AppSettings() @app.post("/jobs/schedule/") diff --git a/docs/settings.md b/docs/settings.md index 1705f3b..3020adf 100644 --- a/docs/settings.md +++ b/docs/settings.md @@ -94,7 +94,7 @@ import fastapi import fastapi_plugins ... -app = fastapi.FastAPI() +app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.get_config() @app.get("/") diff --git a/fastapi_plugins/__init__.py b/fastapi_plugins/__init__.py index 1b91933..d0b52af 100644 --- a/fastapi_plugins/__init__.py +++ b/fastapi_plugins/__init__.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote fastapi_plugins --------------- @@ -13,11 +13,13 @@ from __future__ import absolute_import -from .plugin import * # noqa F401 F403 -from .control import * # noqa F401 F403 -from ._redis import * # noqa F401 F403 -from .scheduler import * # noqa F401 F403 -from .settings import * # noqa F401 F403 +from .plugin import * # noqa F401 F403 +from .control import * # noqa F401 F403 +from .logger import * # noqa F401 F403 +from .middleware import * # noqa F401 F403 +from ._redis import * # noqa F401 F403 +from .scheduler import * # noqa F401 F403 +from .settings import * # noqa F401 F403 from .version import VERSION # try: @@ -37,7 +39,7 @@ __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, madkote' +__copyright__ = 'Copyright 2021, madkote' # TODO: provide a generic cache type (redis, memcached, in-memory) # and share some settings. Module/Sub-Pack cache @@ -55,6 +57,3 @@ # TODO: look at fastapi-cache (memcache?) look at mqtt? # ... more? - -# TODO: logging - simple? or more complex example? -> will decide later -# what is an exact use case? log requests? log extra information? diff --git a/fastapi_plugins/_redis.py b/fastapi_plugins/_redis.py index a3da486..185a3bc 100644 --- a/fastapi_plugins/_redis.py +++ b/fastapi_plugins/_redis.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote fastapi_plugins._redis ---------------------- @@ -36,7 +36,7 @@ ] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, madkote' +__copyright__ = 'Copyright 2021, madkote' class RedisError(PluginError): diff --git a/fastapi_plugins/logger.py b/fastapi_plugins/logger.py new file mode 100644 index 0000000..e75ab5a --- /dev/null +++ b/fastapi_plugins/logger.py @@ -0,0 +1,257 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- +# fastapi_plugins.logger +''' +:author: madkote +:contact: madkote(at)bluewin.ch +:copyright: Copyright 2021, madkote RES + +fastapi_plugins.logger +---------------------- +Logging plugin +''' + +from __future__ import absolute_import + +import datetime +import enum +import logging +import numbers +import queue +import sys +import typing + +import fastapi +import pydantic +import starlette.requests + +from pythonjsonlogger import jsonlogger + +from .plugin import PluginError +from .plugin import PluginSettings +from .plugin import Plugin + +from .control import ControlHealthMixin + +from .version import VERSION + +__all__ = [ + 'LoggingError', 'LoggingStyle', 'LoggingHandlerType', 'LoggingSettings', + 'LoggingPlugin', 'log_plugin', 'log_adapter', 'depends_logging' +] +__author__ = 'madkote ' +__version__ = '.'.join(str(x) for x in VERSION) +__copyright__ = 'Copyright 2021, madkote RES' + + +class QueueHandler(logging.Handler): + def __init__(self, *args, mqueue=None, **kwargs): + super(QueueHandler, self).__init__(*args, **kwargs) + self.mqueue = mqueue if mqueue is not None else queue.Queue() + + def emit(self, record): + self.mqueue.put(self.format(record)) + + +class JsonFormatter(jsonlogger.JsonFormatter): + def add_fields(self, log_record, record, message_dict): + super(JsonFormatter, self).add_fields( + log_record, + record, + message_dict + ) + if not log_record.get('timestamp'): + # this doesn't use record.created, so it is slightly off + now = datetime.datetime.utcnow().strftime('%Y-%m-%dT%H:%M:%S.%fZ') + log_record['timestamp'] = now + if log_record.get('level'): + log_record['level'] = log_record['level'].upper() + else: + log_record['level'] = record.levelname + if not log_record.get('name'): + log_record['name'] = record.name + + +class LogfmtFormatter(logging.Formatter): + # from https://github.com/jkakar/logfmt-python + def format_line(self, extra: typing.Dict) -> str: + outarr = [] + for k, v in extra.items(): + if v is None: + outarr.append('%s=' % k) + continue + if isinstance(v, bool): + v = 'true' if v else 'false' + elif isinstance(v, numbers.Number): + pass + else: + if isinstance(v, (dict, object)): + v = str(v) + v = '"%s"' % v.replace('"', '\\"') + outarr.append('%s=%s' % (k, v)) + return ' '.join(outarr) + + def format(self, record): + return ' '.join( + [ + 'at=%s' % record.levelname, + 'msg="%s"' % record.getMessage().replace('"', '\\"'), + 'process=%s' % record.processName, + self.format_line(getattr(record, 'context', {})), + ] + ).strip() + + +class LoggerLogfmt(logging.Logger): + def makeRecord( + self, + name, + level, + fn, + lno, + msg, + args, + exc_info, + func=None, + extra=None, + sinfo=None + ): + factory = logging.getLogRecordFactory() + rv = factory(name, level, fn, lno, msg, args, exc_info, func, sinfo) + if extra is not None: + rv.__dict__['context'] = dict(**extra) + return rv + + +class LoggerAdapter(logging.LoggerAdapter): + def process(self, msg, kwargs): + _extra = kwargs.get('extra', {}) + kwargs["extra"] = dict(**self.extra) + kwargs["extra"].update(**_extra) + return msg, kwargs + + +class LoggingError(PluginError): + pass + + +@enum.unique +class LoggingStyle(str, enum.Enum): + logfmt = 'logfmt' + logjson = 'json' + logtxt = 'txt' + + +@enum.unique +class LoggingHandlerType(str, enum.Enum): + loglist = 'list' + logstdout = 'stdout' + + +class LoggingSettings(PluginSettings): + logging_level: int = logging.WARNING + logging_style: LoggingStyle = LoggingStyle.logtxt + logging_handler: LoggingHandlerType = LoggingHandlerType.logstdout + logging_fmt: str = None + + +class LoggingPlugin(Plugin, ControlHealthMixin): + DEFAULT_CONFIG_CLASS: pydantic.BaseSettings = LoggingSettings + + def _create_logger( + self, + name: str, + config: pydantic.BaseSettings=None + ) -> logging.Logger: + logger_klass = None + # + if config.logging_handler == LoggingHandlerType.logstdout: + handler = logging.StreamHandler(stream=sys.stdout) + elif config.logging_handler == LoggingHandlerType.loglist: + handler = QueueHandler() + # + if config.logging_style == LoggingStyle.logtxt: + formatter = logging.Formatter(fmt=config.logging_fmt) + elif config.logging_style == LoggingStyle.logfmt: + formatter = LogfmtFormatter() + logger_klass = LoggerLogfmt + elif config.logging_style == LoggingStyle.logjson: + formatter = JsonFormatter() + else: + raise LoggingError( + 'unknown logging format style %s' % config.logging_style + ) + if logger_klass is not None: + _original_logger_klass = logging.getLoggerClass() + try: + logging.setLoggerClass(logger_klass) + logger = logging.getLogger(name) + finally: + logging.setLoggerClass(_original_logger_klass) + else: + logger = logging.getLogger(name) + # + logger.setLevel(config.logging_level) + handler.setLevel(config.logging_level) + handler.setFormatter(formatter) + logger.addHandler(handler) + return logger + + def _on_init(self) -> None: + self.config = None + self.logger = None + + async def _on_call(self) -> logging.Logger: + if self.logger is None: + raise LoggingError('Logging is not initialized') + return self.logger + + async def init_app( + self, + app: fastapi.FastAPI, + config: pydantic.BaseSettings=None, + *, + name: str=None + ) -> None: + self.config = config or self.DEFAULT_CONFIG_CLASS() + if self.config is None: + raise LoggingError('Logging configuration is not initialized') + elif not isinstance(self.config, self.DEFAULT_CONFIG_CLASS): + raise LoggingError('Logging configuration is not valid') + name = name if name else __name__.split('.')[0] + self.logger = self._create_logger(name, self.config) + app.state.PLUGIN_LOGGER = self + + async def init(self) -> None: + self.logger.info('Logging plugin is ON') + + async def terminate(self) -> None: + self.logger.info('Logging plugin is OFF') + self.config = None + self.logger = None + + async def health(self) -> typing.Dict: + return dict(level=self.logger.level, style=self.config.logging_style) + + +log_plugin = LoggingPlugin() + + +async def log_adapter( + logger: typing.Union[logging.Logger, LoggerAdapter], + extra: typing.Dict=None +) -> LoggerAdapter: + if extra is None: + extra = {} + if isinstance(logger, logging.Logger): + return LoggerAdapter(logger, extra) + else: + _extra = dict(**logger.extra) + _extra.update(**extra) + return LoggerAdapter(logger.logger, _extra) + + +async def depends_logging( + conn: starlette.requests.HTTPConnection +) -> logging.Logger: + return await conn.app.state.PLUGIN_LOGGER() diff --git a/fastapi_plugins/memcached.py b/fastapi_plugins/memcached.py index 820d4b0..d1a2433 100644 --- a/fastapi_plugins/memcached.py +++ b/fastapi_plugins/memcached.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote fastapi_plugins.memcached ------------------------- @@ -39,7 +39,7 @@ ] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, madkote' +__copyright__ = 'Copyright 2021, madkote' class MemcachedError(PluginError): diff --git a/fastapi_plugins/middleware.py b/fastapi_plugins/middleware.py new file mode 100644 index 0000000..7127619 --- /dev/null +++ b/fastapi_plugins/middleware.py @@ -0,0 +1,47 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- +# fastapi_plugins.middleware +''' +:author: madkote +:contact: madkote(at)bluewin.ch +:copyright: Copyright 2021, madkote RES + +fastapi_plugins.middleware +-------------------------- +Middleware utilities and collections +''' + +from __future__ import absolute_import + +import typing + +import fastapi +import starlette.middleware.cors + +from .version import VERSION + +__all__ = ['register_middleware'] +__author__ = 'madkote ' +__version__ = '.'.join(str(x) for x in VERSION) +__copyright__ = 'Copyright 2021, madkote RES' + + +def register_middleware( + app: fastapi.FastAPI, + middleware: typing.List[typing.Tuple[type, typing.Any]]=None +) -> fastapi.FastAPI: + if not middleware: + middleware = [ + ( + starlette.middleware.cors.CORSMiddleware, + dict( + allow_origins=["*"], + allow_credentials=True, + allow_methods=["*"], + allow_headers=["*"] + ) + ) + ] + for mw_klass, options in middleware: + app.add_middleware(mw_klass, **options) + return app diff --git a/fastapi_plugins/plugin.py b/fastapi_plugins/plugin.py index f533ca6..811d846 100644 --- a/fastapi_plugins/plugin.py +++ b/fastapi_plugins/plugin.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote fastapi_plugins.plugin ---------------------- @@ -24,7 +24,7 @@ __all__ = ['PluginError', 'PluginSettings', 'Plugin'] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, madkote' +__copyright__ = 'Copyright 2021, madkote' class PluginError(Exception): diff --git a/fastapi_plugins/scheduler.py b/fastapi_plugins/scheduler.py index 040b05c..91caa9e 100644 --- a/fastapi_plugins/scheduler.py +++ b/fastapi_plugins/scheduler.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote fastapi_plugins.scheduler ------------------------- @@ -35,7 +35,7 @@ ] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, madkote' +__copyright__ = 'Copyright 2021, madkote' class SchedulerError(PluginError): diff --git a/fastapi_plugins/version.py b/fastapi_plugins/version.py index d9818be..df29f27 100644 --- a/fastapi_plugins/version.py +++ b/fastapi_plugins/version.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2019, madkote +:copyright: Copyright 2021, madkote fastapi_plugins.version ----------------------- @@ -13,9 +13,9 @@ from __future__ import absolute_import -VERSION = (0, 8, 2) +VERSION = (0, 9, 0) __all__ = [] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2019, madkote' +__copyright__ = 'Copyright 2021, madkote' diff --git a/scripts/demo_app.py b/scripts/demo_app.py index 232acf3..784a8e5 100644 --- a/scripts/demo_app.py +++ b/scripts/demo_app.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2019, madkote +:copyright: Copyright 2021, madkote demo ---- @@ -16,6 +16,7 @@ from __future__ import absolute_import import asyncio +import logging import typing import uuid @@ -56,9 +57,11 @@ class AppSettings( fastapi_plugins.ControlSettings, fastapi_plugins.RedisSettings, fastapi_plugins.SchedulerSettings, + fastapi_plugins.LoggingSettings, MemcachedSettings, ): api_name: str = str(__name__) + logging_level: int = logging.DEBUG @fastapi_plugins.registered_configuration(name='sentinel') @@ -72,16 +75,19 @@ class AppSettingsLocal(AppSettings): pass -app = fastapi.FastAPI() +app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.get_config() @app.get("/") async def root_get( cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), - conf: pydantic.BaseSettings=fastapi.Depends(fastapi_plugins.depends_config) # noqa E501 + conf: pydantic.BaseSettings=fastapi.Depends(fastapi_plugins.depends_config), # noqa E501 + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging) ) -> typing.Dict: - return dict(ping=await cache.ping(), api_name=conf.api_name) + ping = await cache.ping() + logger.debug('root_get', extra=dict(ping=ping, api_name=conf.api_name)) + return dict(ping=ping, api_name=conf.api_name) @app.post("/jobs/schedule/") @@ -89,22 +95,30 @@ async def job_post( timeout: int=fastapi.Query(..., title='the job sleep time'), cache: aioredis.Redis=fastapi.Depends(fastapi_plugins.depends_redis), scheduler: aiojobs.Scheduler=fastapi.Depends(fastapi_plugins.depends_scheduler), # noqa E501 + logger: logging.Logger=fastapi.Depends(fastapi_plugins.depends_logging) ) -> str: async def coro(job_id, timeout, cache): await cache.set(job_id, 'processing') try: await asyncio.sleep(timeout) if timeout == 8: + logger.critical('Ugly erred job %s' % job_id) raise Exception('ugly error') except asyncio.CancelledError: await cache.set(job_id, 'canceled') + logger.warning('Cancel job %s' % job_id) except Exception: await cache.set(job_id, 'erred') + logger.error('Erred job %s' % job_id) else: await cache.set(job_id, 'success') + logger.info('Done job %s' % job_id) job_id = str(uuid.uuid4()).replace('-', '') + logger = await fastapi_plugins.log_adapter(logger, extra=dict(job_id=job_id, timeout=timeout)) # noqa E501 + logger.info('New job %s' % job_id) await cache.set(job_id, 'pending') + logger.debug('Pending job %s' % job_id) await scheduler.spawn(coro(job_id, timeout, cache)) return job_id @@ -137,6 +151,8 @@ async def memcached_demo_post( async def on_startup() -> None: await fastapi_plugins.config_plugin.init_app(app, config) await fastapi_plugins.config_plugin.init() + await fastapi_plugins.log_plugin.init_app(app, config, name=__name__) + await fastapi_plugins.log_plugin.init() await memcached_plugin.init_app(app, config) await memcached_plugin.init() await fastapi_plugins.redis_plugin.init_app(app, config=config) @@ -158,4 +174,5 @@ async def on_shutdown() -> None: await fastapi_plugins.scheduler_plugin.terminate() await fastapi_plugins.redis_plugin.terminate() await memcached_plugin.terminate() + await fastapi_plugins.log_plugin.terminate() await fastapi_plugins.config_plugin.terminate() diff --git a/setup.py b/setup.py index f8e6dbf..60edf93 100644 --- a/setup.py +++ b/setup.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2019, madkote +:copyright: Copyright 2021, madkote setup ----- @@ -24,7 +24,7 @@ from setuptools import find_packages __author__ = 'madkote ' -__copyright__ = 'Copyright 2019, madkote' +__copyright__ = 'Copyright 2021, madkote' if sys.version_info < (3, 6, 0): @@ -87,6 +87,9 @@ def _read(): 'pydantic>=0.32.*', 'tenacity>=6.2.*' ] +REQUIRES_INSTALL += [ + 'python-json-logger>=2.0.*' +] REQUIRES_INSTALL += [ 'aioredis<=1.3.1' ] diff --git a/tests/conftest.py b/tests/conftest.py index 02ccec2..9d5052e 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -4,7 +4,7 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote tests.conftest -------------- @@ -18,7 +18,7 @@ __all__ = [] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2019, madkote' +__copyright__ = 'Copyright 2021, madkote' def pytest_configure(config): @@ -40,3 +40,6 @@ def pytest_configure(config): config.addinivalue_line( "markers", "settings: mark test related to Settings and Configuration" ) + config.addinivalue_line( + "markers", "logger: mark test related to Logger" + ) diff --git a/tests/test_control.py b/tests/test_control.py index eef0abd..9bf4f1a 100644 --- a/tests/test_control.py +++ b/tests/test_control.py @@ -8,7 +8,7 @@ tests.test_control ------------------ -Module +Control plugin tests ''' from __future__ import absolute_import @@ -117,7 +117,7 @@ def tearDown(self): def make_app(self, config=None, version=None, environ=None, plugins=None): if plugins is None: plugins = [] - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) if config is None: config = fastapi_plugins.ControlSettings() @@ -186,7 +186,7 @@ async def _test(): def test_controller_health_plugin_ok(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.ControlSettings() dummy = DummyPluginHealthOK() await dummy.init_app(app, config) @@ -219,7 +219,7 @@ async def _test(): def test_controller_health_plugin_notdefined(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.ControlSettings() dummy = DummyPluginHealthNotDefined() await dummy.init_app(app, config) @@ -252,7 +252,7 @@ async def _test(): def test_controller_health_plugin_failing(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.ControlSettings() dummy = DummyPluginHealthFail() await dummy.init_app(app, config) diff --git a/tests/test_logger.py b/tests/test_logger.py new file mode 100644 index 0000000..a65b1cb --- /dev/null +++ b/tests/test_logger.py @@ -0,0 +1,412 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- +# tests.test_logger +''' +:author: madkote +:contact: madkote(at)bluewin.ch +:copyright: Copyright 2021, madkote + +tests.test_logger +----------------- +Logger tests +''' + +from __future__ import absolute_import + +import asyncio +import copy +import json +import inspect +import logging +import unittest + +import fastapi +import pytest + +import fastapi_plugins + +from . import VERSION + +__all__ = [] +__author__ = 'madkote ' +__version__ = '.'.join(str(x) for x in VERSION) +__copyright__ = 'Copyright 2021, madkote' + + +@pytest.mark.logger +class LoggerTest(unittest.TestCase): + def test_basic(self): + async def _test(): + level = logging.WARNING + name = 'fastapi_plugins' + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings() + await fastapi_plugins.log_plugin.init_app(app=app, config=config) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + def test_name_and_level(self): + name = 'fastapi_plugins_%s' % inspect.stack()[0][3] + + async def _test(): + level = logging.CRITICAL + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings(logging_level=level) + await fastapi_plugins.log_plugin.init_app( + app=app, + config=config, + name=name + ) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + def test_format_default(self): + name = 'fastapi_plugins_%s' % inspect.stack()[0][3] + + async def _test(): + level = logging.DEBUG + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings( + logging_level=level, + logging_style=fastapi_plugins.LoggingStyle.logtxt, + logging_handler=fastapi_plugins.LoggingHandlerType.loglist + ) + await fastapi_plugins.log_plugin.init_app( + app=app, + config=config, + name=name + ) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + # + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + # + logger.debug('Hello') + logger.info('World', extra=dict(planet='earth')) + logger.warning('Echo', extra=dict(planet='earth', satellite=['moon'])) # noqa E501 + # + h = logger.handlers[0] + res = [r for r in h.mqueue.queue][1:] + exp = ['Hello', 'World', 'Echo'] + try: + self.assertTrue(exp == res, 'different logs') + except Exception as e: + print() + print('---- expected ------') + print(exp) + print('--------------------') + print() + print('---- records ------') + print(res) + print('--------------------') + print() + raise e + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + def test_format_json(self): + name = 'fastapi_plugins_%s' % inspect.stack()[0][3] + + async def _test(): + def _preproc_exp(_r): + _res = [] + for x in _r: + x1 = copy.deepcopy(x) + x1.pop('timestamp') + _res.append(x1) + return _res + + def _preproc_res(_r): + _res = [] + for x in _r: + x1 = json.loads(x) + x1.pop('timestamp') + _res.append(x1) + return _res + + level = logging.DEBUG + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings( + logging_level=level, + logging_style=fastapi_plugins.LoggingStyle.logjson, + logging_handler=fastapi_plugins.LoggingHandlerType.loglist + ) + await fastapi_plugins.log_plugin.init_app( + app=app, + config=config, + name=name + ) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + # + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + # + logger.debug('Hello') + logger.info('World', extra=dict(planet='earth')) + logger.warning('Echo', extra=dict(planet='earth', satellite=['moon'])) # noqa E501 + # + h = logger.handlers[0] + res = [r for r in h.mqueue.queue][1:] + res = _preproc_res(res) + exp = [ + {"message": "Hello", "timestamp": "2021-09-23T13:44:01.066467Z", "level": "DEBUG", "name": name}, # noqa E501 + {"message": "World", "planet": "earth", "timestamp": "2021-09-23T13:44:01.066581Z", "level": "INFO", "name": name}, # noqa E501 + {"message": "Echo", "planet": "earth", "satellite": ["moon"], "timestamp": "2021-09-23T13:44:01.066690Z", "level": "WARNING", "name": name} # noqa E501 + ] + exp = _preproc_exp(exp) + try: + self.assertTrue(exp == res, 'different logs') + except Exception as e: + print() + print('---- expected ------') + print(exp) + print('--------------------') + print() + print('---- records ------') + print(res) + print('--------------------') + print() + raise e + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + def test_format_logfmt(self): + name = 'fastapi_plugins_%s' % inspect.stack()[0][3] + + async def _test(): + level = logging.DEBUG + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings( + logging_level=level, + logging_style=fastapi_plugins.LoggingStyle.logfmt, + logging_handler=fastapi_plugins.LoggingHandlerType.loglist + ) + await fastapi_plugins.log_plugin.init_app( + app=app, + config=config, + name=name + ) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + # + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + # + logger.debug('Hello') + logger.info('World', extra=dict(planet='earth')) + logger.warning('Echo', extra=dict(planet='earth', satellite=['moon'])) # noqa E501 + # + h = logger.handlers[0] + res = [r for r in h.mqueue.queue][1:] + exp = [ + 'at=DEBUG msg="Hello" process=MainProcess', + 'at=INFO msg="World" process=MainProcess planet="earth"', + 'at=WARNING msg="Echo" process=MainProcess planet="earth" satellite="[\'moon\']"' # noqa E501 + ] + try: + self.assertTrue(exp == res, 'different logs') + except Exception as e: + print() + print('---- expected ------') + print(exp) + print('--------------------') + print() + print('---- records ------') + print(res) + print('--------------------') + print() + raise e + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + def test_adapter(self): + name = 'fastapi_plugins_%s' % inspect.stack()[0][3] + + async def _test(): + def _preproc_exp(_r): + _res = [] + for x in _r: + x1 = copy.deepcopy(x) + x1.pop('timestamp') + _res.append(x1) + return _res + + def _preproc_res(_r): + _res = [] + for x in _r: + x1 = json.loads(x) + x1.pop('timestamp') + _res.append(x1) + return _res + + level = logging.DEBUG + # + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) + config = fastapi_plugins.LoggingSettings( + logging_level=level, + logging_style=fastapi_plugins.LoggingStyle.logjson, + logging_handler=fastapi_plugins.LoggingHandlerType.loglist + ) + await fastapi_plugins.log_plugin.init_app( + app=app, + config=config, + name=name + ) + await fastapi_plugins.log_plugin.init() + try: + logger = await fastapi_plugins.log_plugin() + # + exp = name + res = logger.name + self.assertTrue( + exp == res, + 'logging name mismatch %s != %s' % (exp, res) + ) + exp = level + res = logger.level + self.assertTrue( + exp == res, + 'logging level mismatch %s != %s' % (exp, res) + ) + # + logger.debug('Hello') + logger = await fastapi_plugins.log_adapter(logger, extra=dict(planet='earth')) # noqa E501 + logger.info('World') + logger = await fastapi_plugins.log_adapter(logger, extra=dict(satellite=['moon'])) # noqa E501 + logger.warning('Echo') + # + h = logger.logger.handlers[0] + res = [r for r in h.mqueue.queue][1:] + res = _preproc_res(res) + exp = [ + {"message": "Hello", "timestamp": "2021-09-23T13:44:01.066467Z", "level": "DEBUG", "name": name}, # noqa E501 + {"message": "World", "planet": "earth", "timestamp": "2021-09-23T13:44:01.066581Z", "level": "INFO", "name": name}, # noqa E501 + {"message": "Echo", "planet": "earth", "satellite": ["moon"], "timestamp": "2021-09-23T13:44:01.066690Z", "level": "WARNING", "name": name} # noqa E501 + ] + exp = _preproc_exp(exp) + try: + self.assertTrue(exp == res, 'different logs') + except Exception as e: + print() + print('---- expected ------') + print(exp) + print('--------------------') + print() + print('---- records ------') + print(res) + print('--------------------') + print() + raise e + finally: + await fastapi_plugins.log_plugin.terminate() + + event_loop = asyncio.new_event_loop() + asyncio.set_event_loop(event_loop) + coro = asyncio.coroutine(_test) + event_loop.run_until_complete(coro()) + event_loop.close() + + +if __name__ == "__main__": + # import sys;sys.argv = ['', 'Test.testName'] + unittest.main() diff --git a/tests/test_memcached.py b/tests/test_memcached.py index fac6479..414ec73 100644 --- a/tests/test_memcached.py +++ b/tests/test_memcached.py @@ -4,11 +4,11 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote tests.test_memcached -------------------- -Module +Memcached tests ''' from __future__ import absolute_import @@ -18,6 +18,7 @@ import uuid import fastapi +import fastapi_plugins import pytest from . import VERSION @@ -26,7 +27,7 @@ __all__ = [] __author__ = 'roman-telepathy-ai ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2020, Telepathy Labs' +__copyright__ = 'Copyright 2021, Telepathy Labs' @pytest.mark.memcached @@ -42,7 +43,7 @@ def test_connect(self): from fastapi_plugins.memcached import memcached_plugin async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = self.fixture_get_config() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() @@ -58,7 +59,7 @@ def test_ping(self): from fastapi_plugins.memcached import memcached_plugin async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = self.fixture_get_config() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() @@ -79,7 +80,7 @@ def test_health(self): from fastapi_plugins.memcached import memcached_plugin async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = self.fixture_get_config() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() @@ -107,7 +108,7 @@ def test_version(self): from fastapi_plugins.memcached import memcached_plugin async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = self.fixture_get_config() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() @@ -128,7 +129,7 @@ def test_get_set(self): from fastapi_plugins.memcached import memcached_plugin async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = self.fixture_get_config() await memcached_plugin.init_app(app=app, config=config) await memcached_plugin.init() diff --git a/tests/test_redis.py b/tests/test_redis.py index 88651b3..580fff8 100644 --- a/tests/test_redis.py +++ b/tests/test_redis.py @@ -4,11 +4,11 @@ ''' :author: madkote :contact: madkote(at)bluewin.ch -:copyright: Copyright 2020, madkote +:copyright: Copyright 2021, madkote tests.test_redis ------------ -Package +---------------- +Redis tests ''' from __future__ import absolute_import @@ -29,7 +29,7 @@ __all__ = [] __author__ = 'madkote ' __version__ = '.'.join(str(x) for x in VERSION) -__copyright__ = 'Copyright 2019, madkote' +__copyright__ = 'Copyright 2021, madkote' # def redis_must_be_running(cls): @@ -57,7 +57,7 @@ class RedisTest(unittest.TestCase): def test_connect_redis_url(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_url='redis://localhost:6379/1' ) @@ -73,7 +73,7 @@ async def _test(): def test_connect(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings() await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() @@ -87,7 +87,7 @@ async def _test(): def test_ping(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings() await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() @@ -106,7 +106,7 @@ async def _test(): def test_health(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings() await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() @@ -132,7 +132,7 @@ async def _test(): def test_get_set(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings() await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() @@ -156,7 +156,7 @@ def test_get_set_ttl(self): redis_ttl = 61 async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings(redis_ttl=redis_ttl) await fastapi_plugins.redis_plugin.init_app(app=app, config=config) await fastapi_plugins.redis_plugin.init() @@ -184,7 +184,7 @@ async def _test(): class RedisSentinelTest(unittest.TestCase): def test_connect(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_type='sentinel', redis_sentinels='localhost:26379' @@ -201,7 +201,7 @@ async def _test(): def test_ping(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_type='sentinel', redis_sentinels='localhost:26379' @@ -223,7 +223,7 @@ async def _test(): def test_health(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_type='sentinel', redis_sentinels='localhost:26379' @@ -252,7 +252,7 @@ async def _test(): def test_get_set(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_type='sentinel', redis_sentinels='localhost:26379' @@ -279,7 +279,7 @@ def test_get_set_ttl(self): redis_ttl = 61 async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.RedisSettings( redis_type='sentinel', redis_sentinels='localhost:26379', diff --git a/tests/test_scheduler.py b/tests/test_scheduler.py index b9eaa39..9468426 100644 --- a/tests/test_scheduler.py +++ b/tests/test_scheduler.py @@ -8,7 +8,7 @@ tests.test_scheduler -------------------- -Module +Scheduler tests ''' from __future__ import absolute_import @@ -45,7 +45,7 @@ def tearDown(self): pass def make_app(self, config=None): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) if config is None: class AppSettings( fastapi_plugins.RedisSettings, @@ -112,7 +112,7 @@ async def on_shutdown() -> None: def test_basic(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.SchedulerSettings() await fastapi_plugins.scheduler_plugin.init_app(app=app, config=config) # noqa E501 await fastapi_plugins.scheduler_plugin.init() @@ -145,7 +145,7 @@ async def coro(name, timeout): def test_health(self): async def _test(): - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.SchedulerSettings() await fastapi_plugins.scheduler_plugin.init_app(app=app, config=config) # noqa E501 await fastapi_plugins.scheduler_plugin.init() diff --git a/tests/test_settings.py b/tests/test_settings.py index c631333..9d93983 100644 --- a/tests/test_settings.py +++ b/tests/test_settings.py @@ -7,8 +7,8 @@ :copyright: Copyright 2021, madkote RES tests.test_settings ---------- -Module +------------------- +Settings tests ''' from __future__ import absolute_import @@ -358,7 +358,7 @@ class MyConfigDocker(fastapi_plugins.PluginSettings): class MyConfigLocal(fastapi_plugins.PluginSettings): api_name: str = 'local' - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.get_config() await fastapi_plugins.config_plugin.init_app(app=app, config=config) # noqa E501 @@ -391,7 +391,7 @@ class MyConfigDocker(fastapi_plugins.PluginSettings): class MyConfigLocal(fastapi_plugins.PluginSettings): api_name: str = 'local' - app = fastapi.FastAPI() + app = fastapi_plugins.register_middleware(fastapi.FastAPI()) config = fastapi_plugins.get_config() await fastapi_plugins.config_plugin.init_app(app=app, config=config) # noqa E501