search

AirbusDefenceAndSpace / pesto

PESTO provides a set of tools to ease the process of packaging a Python algorithm as a processing web service into a docker image. The deployment of a web service becomes now as easy as filling few configuration files.
https://airbusdefenceandspace.github.io/pesto
Apache License 2.0
24 stars 8 forks source link

Customize Pesto logger #8

Closed gpo-geo closed 3 years ago

gpo-geo commented 3 years ago

This is a feature request to enable pesto logger customization.

A few nice-to-have on this feature:

tapiab commented 3 years ago

Please have a look to https://github.com/AirbusDefenceAndSpace/pesto/pull/6

The new logging solution based on loguru intercepts FastAPI logs and allow formatting and customization from both code and environment variables (for example, LOG_SERIALIZATION_TRUE serialize logs in json).

Could you provide us feedback on this ?

gpo-geo commented 3 years ago

The env variable: LOGURU_SERIALIZE=TRUE allows to serialize parts of the logs.

Example:

INFO:     Started server process [1]
{"text": "2021-10-28 09:28:12.113 | INFO     | uvicorn.server:serve:84 - Started server process [1]\n", "record": {"elapsed": {"repr": "0:00:00.053584", "seconds": 0.053584}, "exception": null, "extra": {}, "file": {"name": "server.py", "path": "/usr/local/lib/python3.8/site-packages/uvicorn/server.py"}, "function": "serve", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 84, "message": "Started server process [1]", "module": "server", "name": "uvicorn.server", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.113138+00:00", "timestamp": 1635413292.113138}}}
INFO:     Waiting for application startup.
{"text": "2021-10-28 09:28:12.113 | INFO     | uvicorn.lifespan.on:startup:45 - Waiting for application startup.\n", "record": {"elapsed": {"repr": "0:00:00.054123", "seconds": 0.054123}, "exception": null, "extra": {}, "file": {"name": "on.py", "path": "/usr/local/lib/python3.8/site-packages/uvicorn/lifespan/on.py"}, "function": "startup", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 45, "message": "Waiting for application startup.", "module": "on", "name": "uvicorn.lifespan.on", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.113677+00:00", "timestamp": 1635413292.113677}}}
{"text": "2021-10-28 09:28:12.114 | INFO     | pesto.ws.service.process:init:36 - ProcessService.init() ...\n", "record": {"elapsed": {"repr": "0:00:00.054650", "seconds": 0.05465}, "exception": null, "extra": {}, "file": {"name": "process.py", "path": "/usr/local/lib/python3.8/site-packages/pesto/ws/service/process.py"}, "function": "init", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 36, "message": "ProcessService.init() ...", "module": "process", "name": "pesto.ws.service.process", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.114204+00:00", "timestamp": 1635413292.114204}}}
{"text": "2021-10-28 09:28:12.114 | INFO     | pesto.ws.core.utils:load_class:26 - loading class : [algorithm.process.Process]\n", "record": {"elapsed": {"repr": "0:00:00.054971", "seconds": 0.054971}, "exception": null, "extra": {}, "file": {"name": "utils.py", "path": "/usr/local/lib/python3.8/site-packages/pesto/ws/core/utils.py"}, "function": "load_class", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 26, "message": "loading class : [algorithm.process.Process]", "module": "utils", "name": "pesto.ws.core.utils", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.114525+00:00", "timestamp": 1635413292.114525}}}
{"text": "2021-10-28 09:28:12.116 | INFO     | pesto.ws.service.process:init:39 - ProcessService.on_start() ...\n", "record": {"elapsed": {"repr": "0:00:00.056557", "seconds": 0.056557}, "exception": null, "extra": {}, "file": {"name": "process.py", "path": "/usr/local/lib/python3.8/site-packages/pesto/ws/service/process.py"}, "function": "init", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 39, "message": "ProcessService.on_start() ...", "module": "process", "name": "pesto.ws.service.process", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.116111+00:00", "timestamp": 1635413292.116111}}}
      .-.
     (o.o)
      |=|
     __|__
   //.=|=.\
  // .=|=. \
  \ .=|=. //
   \(_=_)//
    (:| |:)
     || ||
     () ()
     || ||
     || ||
l42 ==' '==
{"text": "2021-10-28 09:28:12.116 | INFO     | pesto.ws.service.process:init:41 - ProcessService.on_start() ... Done !\n", "record": {"elapsed": {"repr": "0:00:00.056926", "seconds": 0.056926}, "exception": null, "extra": {}, "file": {"name": "process.py", "path": "/usr/local/lib/python3.8/site-packages/pesto/ws/service/process.py"}, "function": "init", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 41, "message": "ProcessService.on_start() ... Done !", "module": "process", "name": "pesto.ws.service.process", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.116480+00:00", "timestamp": 1635413292.11648}}}
{"text": "2021-10-28 09:28:12.116 | INFO     | pesto.ws.service.process:init:43 - ProcessService.init() ... Done !\n", "record": {"elapsed": {"repr": "0:00:00.057215", "seconds": 0.057215}, "exception": null, "extra": {}, "file": {"name": "process.py", "path": "/usr/local/lib/python3.8/site-packages/pesto/ws/service/process.py"}, "function": "init", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 43, "message": "ProcessService.init() ... Done !", "module": "process", "name": "pesto.ws.service.process", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.116769+00:00", "timestamp": 1635413292.116769}}}
INFO:     Application startup complete.
{"text": "2021-10-28 09:28:12.117 | INFO     | uvicorn.lifespan.on:startup:59 - Application startup complete.\n", "record": {"elapsed": {"repr": "0:00:00.057591", "seconds": 0.057591}, "exception": null, "extra": {}, "file": {"name": "on.py", "path": "/usr/local/lib/python3.8/site-packages/uvicorn/lifespan/on.py"}, "function": "startup", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 59, "message": "Application startup complete.", "module": "on", "name": "uvicorn.lifespan.on", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.117145+00:00", "timestamp": 1635413292.117145}}}
INFO:     Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)
{"text": "2021-10-28 09:28:12.118 | INFO     | uvicorn.server:_log_started_message:217 - Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)\n", "record": {"elapsed": {"repr": "0:00:00.059256", "seconds": 0.059256}, "exception": null, "extra": {}, "file": {"name": "server.py", "path": "/usr/local/lib/python3.8/site-packages/uvicorn/server.py"}, "function": "_log_started_message", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 217, "message": "Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)", "module": "server", "name": "uvicorn.server", "process": {"id": 1, "name": "MainProcess"}, "thread": {"id": 139988231759680, "name": "MainThread"}, "time": {"repr": "2021-10-28 09:28:12.118810+00:00", "timestamp": 1635413292.11881}}}
INFO:     172.17.0.1:56600 - "GET /api/v1/describe HTTP/1.1" 200 OK
INFO:     172.17.0.1:56604 - "GET /api/v1/health HTTP/1.1" 200 OK
INFO:     172.17.0.1:56604 - "GET /favicon.ico HTTP/1.1" 404 Not Found

If I understand correctly, a log handler based on loguru is used in pesto to process logs emited from pesto and uvicorn, however logs from fastapi are not handled.

I'll try to play around with this.

tapiab commented 3 years ago

I've managed to format the log with a custom sink for FastAPI : https://github.com/AirbusDefenceAndSpace/pesto/pull/6/commits/3d7b5cd6fc3edf6ceea468a834d0019c4fe42876 I'm going to extend it for uvicorn

tapiab commented 3 years ago

Merged here : https://github.com/AirbusDefenceAndSpace/pesto/pull/6