Merge pull request #25 from madkote/dev_0.14

0.14.x - logging improvements

Author: madkote

CHANGES.md

@@ -1,4 +1,7 @@
 # Changes
+## 0.14.0 (2025-07-10)
+- `[feature]` `orjson` logging format for more performance
+- `[feature]` `logging_memory_*` buffered logging for more performance
 ## 0.13.2 (2025-02-12)
 - `[fix]` `examples` field in `Control` schema
 ## 0.13.1 (2024-06-03)

ENV

@@ -1,6 +1,6 @@
 MIT License
 
-Copyright (c) 2019 RES
+Copyright (c) 2025 RES
 
 Permission is hereby granted, free of charge, to any person obtaining a copy
 of this software and associated documentation files (the "Software"), to deal

LICENSE

@@ -49,7 +49,7 @@ clean: clean-build clean-docker clean-pyc clean-pycache
 
 install: clean
 	@echo $@
-	pip install --no-cache-dir -U pip setuptools twine wheel
+	pip install --no-cache-dir -U build pip setuptools twine wheel
 	pip install --no-cache-dir -U --force-reinstall -r requirements.txt
 	rm -rf build *.egg-info
 	pip uninstall ${PYPACKAGE} -y || true
@@ -62,20 +62,15 @@ demo-app: clean
 	@echo $@
 	uvicorn scripts.demo_app:app
 
-flake: clean
+lint: clean
 	@echo $@
-	flake8 --statistics --ignore E252 ${PYPACKAGE} tests scripts setup.py
+	pdm run lint
 
-bandit: clean
+test-pdm:
 	@echo $@
-	bandit -r ${PYPACKAGE}/ scripts/ demo.py setup.py
-	bandit -s B101 -r tests/
+	pdm run test
 
-test-unit-pytest:
-	@echo $@
-	python -m pytest -v -x tests/ --cov=${PYPACKAGE}
-
-test-unit: clean flake bandit docker-up-test test-unit-pytest docker-down-test
+test-unit: clean docker-up-test test-pdm docker-down-test
 	@echo $@
 
 test-toxtox:
@@ -88,14 +83,18 @@ test-tox: clean docker-up-test test-toxtox docker-down-test
 test: test-unit
 	@echo $@
 
-test-all: clean flake bandit docker-up-test test-unit-pytest test-toxtox docker-down-test
+test-all: clean docker-up-test test-pdm test-toxtox docker-down-test
 	@echo $@
 
-pypi-build: clean test-all
-	@echo $@
-	python setup.py sdist bdist_wheel
+pypi-build-twine:
 	twine check dist/*
 
+pypi-build-wheel:
+	pdm run build
+
+pypi-build: clean test-all pypi-build-wheel pypi-build-twine
+	@echo $@
+
 pypi-upload-test:
 	@echo $@
 	python -m twine upload --repository-url https://test.pypi.org/legacy/ dist/*

Makefile

@@ -72,8 +72,8 @@ async def coro(name, timeout):
         s = await fastapi_plugins.scheduler_plugin()
         # import random
         for i in range(10):
-            await s.spawn(coro(str(i), i/10))
-            # await s.spawn(coro(str(i), i/10 + random.choice([0.1, 0.2, 0.3, 0.4, 0.5])))  # nosec B311
+            await s.spawn(coro(str(i), i / 10))
+            # await s.spawn(coro(str(i), i/10 + random.choice([0.1, 0.2, 0.3, 0.4, 0.5])))  # nosec B311 # noqa
         # print('----------')
         print('- sleep', 5)
         await asyncio.sleep(5.0)
@@ -148,18 +148,18 @@ async def coro(con, name, timeout):
         num_sleep = 0.25
 
         print('- play')
-        l = await fastapi_plugins.log_plugin()
+        logger = 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))
-        l.info('- sleep %s' % num_sleep)
+            await s.spawn(coro(c, str(i), i / 10))
+        logger.info('- sleep %s' % num_sleep)
         # print('- sleep', num_sleep)
         await asyncio.sleep(num_sleep)
-        l.info('- check')
+        logger.info('- check')
         # print('- check')
         for i in range(num_jobs):
-            l.info('%s == %s' % (i, await c.get(str(i))))
+            logger.info('%s == %s' % (i, await c.get(str(i))))
             # print(i, '==', await c.get(str(i)))
     finally:
         print('- terminate')
@@ -186,9 +186,9 @@ class CustomLoggingSettings(fastapi_plugins.LoggingSettings):
 
     class CustomLoggingPlugin(fastapi_plugins.LoggingPlugin):
         def _create_logger(
-            self, 
-            name:str, 
-            config:pydantic_settings.BaseSettings=None
+            self,
+            name: str,
+            config: pydantic_settings.BaseSettings = None
         ) -> logging.Logger:
             import sys
             handler = logging.StreamHandler(stream=sys.stderr)
@@ -227,18 +227,18 @@ class AppSettings(
         num_sleep = 0.25
 
         print('- play')
-        l = await mylog_plugin()
+        logger = 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)
+            await s.spawn(coro(c, str(i), i / 10))
+        logger.info('- sleep %s' % num_sleep)
         # print('- sleep', num_sleep)
         await asyncio.sleep(num_sleep)
-        l.info('- check')
+        logger.info('- check')
         # print('- check')
         for i in range(num_jobs):
-            l.info('%s == %s' % (i, await c.get(str(i))))
+            logger.info('%s == %s' % (i, await c.get(str(i))))
             # print(i, '==', await c.get(str(i)))
     finally:
         print('- terminate')
@@ -248,6 +248,104 @@ class AppSettings(
         print('---demo done')
 
 
+async def test_demo_orjson_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
+
+    print('--- do demo')
+    app = fastapi_plugins.register_middleware(fastapi.FastAPI())
+    config = AppSettings(logging_style=fastapi_plugins.LoggingStyle.logorjson)
+
+    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)
+    await fastapi_plugins.scheduler_plugin.init()
+
+    try:
+        num_jobs = 10
+        num_sleep = 0.25
+
+        print('- play')
+        logger = 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))
+        logger.info('- sleep %s' % num_sleep, extra=dict(bla='bla'))
+        # print('- sleep', num_sleep)
+        await asyncio.sleep(num_sleep)
+        logger.info('- check')
+        # print('- check')
+        for i in range(num_jobs):
+            logger.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 fastapi_plugins.log_plugin.terminate()
+        print('---demo done')
+
+
+async def test_demo_json_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
+
+    print('--- do demo')
+    app = fastapi_plugins.register_middleware(fastapi.FastAPI())
+    config = AppSettings(logging_style=fastapi_plugins.LoggingStyle.logjson)
+
+    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)
+    await fastapi_plugins.scheduler_plugin.init()
+
+    try:
+        num_jobs = 10
+        num_sleep = 0.25
+
+        print('- play')
+        logger = 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))
+        logger.info('- sleep %s' % num_sleep, extra=dict(bla='bla'))
+        # print('- sleep', num_sleep)
+        await asyncio.sleep(num_sleep)
+        logger.info('- check')
+        # print('- check')
+        for i in range(num_jobs):
+            logger.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 fastapi_plugins.log_plugin.terminate()
+        print('---demo done')
+
+
 async def test_memcached():
     print('---test memcached')
     from fastapi_plugins.memcached import MemcachedSettings
@@ -261,7 +359,7 @@ class MoreSettings(AppSettings, MemcachedSettings):
     config = MoreSettings()
     await memcached_plugin.init_app(app=app, config=config)
     await memcached_plugin.init()
-    
+
     c = await memcached_plugin()
     print(await c.get(b'x'))
     print(await c.set(b'x', str(time.time()).encode()))
@@ -270,6 +368,51 @@ class MoreSettings(AppSettings, MemcachedSettings):
     print('---test memcached done')
 
 
+async def test_demo_buffered_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
+
+    print('--- do demo')
+    app = fastapi_plugins.register_middleware(fastapi.FastAPI())
+    config = AppSettings(
+        logging_style=fastapi_plugins.LoggingStyle.logjson,
+        logging_memory_capacity=25
+    )
+
+    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)
+    await fastapi_plugins.scheduler_plugin.init()
+
+    try:
+        num_jobs = 10
+        num_tasks = 30
+
+        logger = await fastapi_plugins.log_plugin()
+        for c_job in range(num_jobs):
+            print(f'----- JOB {c_job}')
+            for c_task in range(num_tasks):
+                logger.info(f'job={c_job} task={c_task} hello world')
+                await asyncio.sleep(0.1)
+            await asyncio.sleep(0.5)
+    finally:
+        print('- terminate')
+        await fastapi_plugins.scheduler_plugin.terminate()
+        await fastapi_plugins.redis_plugin.terminate()
+        await fastapi_plugins.log_plugin.terminate()
+        print('---demo done')
+
+
 # =============================================================================
 # ---
 # =============================================================================
@@ -301,21 +444,49 @@ 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)
+    print('= DEMO CUSTOM LOG')
     loop = asyncio.get_event_loop()
     loop.run_until_complete(test_demo_custom_log())
 
 
+def main_demo_json_log():
+    print(os.linesep * 3)
+    print('=' * 50)
+    print('= DEMO JSON LOG')
+    loop = asyncio.get_event_loop()
+    loop.run_until_complete(test_demo_json_log())
+
+
+def main_demo_orjson_log():
+    print(os.linesep * 3)
+    print('=' * 50)
+    print('= DEMO ORJSON LOG')
+    loop = asyncio.get_event_loop()
+    loop.run_until_complete(test_demo_orjson_log())
+
+
+def main_demo_buffered_log():
+    print(os.linesep * 3)
+    print('=' * 50)
+    print('= DEMO BUFFERED LOG')
+    loop = asyncio.get_event_loop()
+    loop.run_until_complete(test_demo_buffered_log())
+
+
 if __name__ == '__main__':
     main_redis()
     main_scheduler()
     main_demo()
     main_demo_custom_log()
-    #
+    main_demo_json_log()
+    main_demo_orjson_log()
+    main_demo_buffered_log()
+
     try:
         main_memcached()
     except Exception as e:
         print(type(e), e)
-

demo.py

@@ -10,16 +10,22 @@ 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`, ...) 
+  * 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
+  * `json` - JSON format with standard `json`
+  * `orjson` - JSON format with `orjson`
   * `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`.
+* `LOGGING_MEMORY_CAPACITY` - if greater then `0` enable buffered log record output
+  * default is `0` - disabled.
+  * a possible _good_ value for production can be `1024*100`
+* `LOGGING_MEMORY_FLUSH_LEVEL` - logging level to immediately flush logging buffer to the handler
+  * any valid level provided by standard `logging` library (e.g. `10`, `20`, `30`, ...)
 
 ## Example
 ### Application