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

Port to FastAPI & log with loguru #6

Closed tapiab closed 2 years ago

gpo-geo commented 2 years ago

This looks interesting. I have tried on a sample service with LOGURU_SERIALIZE=TRUE, however the messages output for each request are still un-formatted:

> docker run --rm -it -e LOGURU_SERIALIZE=TRUE -p 4000:8080 ws-skeleton:1.0.0.dev0-cpu
INFO:     Started server process [1]
{"text": "2021-10-27 22:21:12.920 | INFO     | uvicorn.server:serve:84 - Started server process [1]\n", "record": {"elapsed": {"repr": "0:00:00.060108", "seconds": 0.060108}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.920404+00:00", "timestamp": 1635373272.920404}}}
INFO:     Waiting for application startup.
{"text": "2021-10-27 22:21:12.920 | INFO     | uvicorn.lifespan.on:startup:45 - Waiting for application startup.\n", "record": {"elapsed": {"repr": "0:00:00.060638", "seconds": 0.060638}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.920934+00:00", "timestamp": 1635373272.920934}}}
{"text": "2021-10-27 22:21:12.921 | INFO     | pesto.ws.service.process:init:36 - ProcessService.init() ...\n", "record": {"elapsed": {"repr": "0:00:00.061118", "seconds": 0.061118}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.921414+00:00", "timestamp": 1635373272.921414}}}
{"text": "2021-10-27 22:21:12.921 | INFO     | pesto.ws.core.utils:load_class:26 - loading class : [algorithm.process.Process]\n", "record": {"elapsed": {"repr": "0:00:00.061409", "seconds": 0.061409}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.921705+00:00", "timestamp": 1635373272.921705}}}
{"text": "2021-10-27 22:21:12.923 | INFO     | pesto.ws.service.process:init:39 - ProcessService.on_start() ...\n", "record": {"elapsed": {"repr": "0:00:00.063247", "seconds": 0.063247}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.923543+00:00", "timestamp": 1635373272.923543}}}
      .-.
     (o.o)
      |=|
     __|__
   //.=|=.\
  // .=|=. \
  \ .=|=. //
   \(_=_)//
    (:| |:)
     || ||
     () ()
     || ||
     || ||
l42 ==' '==
{"text": "2021-10-27 22:21:12.923 | INFO     | pesto.ws.service.process:init:41 - ProcessService.on_start() ... Done !\n", "record": {"elapsed": {"repr": "0:00:00.063668", "seconds": 0.063668}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.923964+00:00", "timestamp": 1635373272.923964}}}
{"text": "2021-10-27 22:21:12.924 | INFO     | pesto.ws.service.process:init:43 - ProcessService.init() ... Done !\n", "record": {"elapsed": {"repr": "0:00:00.063964", "seconds": 0.063964}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.924260+00:00", "timestamp": 1635373272.92426}}}
INFO:     Application startup complete.
{"text": "2021-10-27 22:21:12.924 | INFO     | uvicorn.lifespan.on:startup:59 - Application startup complete.\n", "record": {"elapsed": {"repr": "0:00:00.064377", "seconds": 0.064377}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.924673+00:00", "timestamp": 1635373272.924673}}}
INFO:     Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)
{"text": "2021-10-27 22:21:12.926 | 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.066095", "seconds": 0.066095}, "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": 140656906823488, "name": "MainThread"}, "time": {"repr": "2021-10-27 22:21:12.926391+00:00", "timestamp": 1635373272.926391}}}
INFO:     172.17.0.1:45342 - "GET /api/v1/describe HTTP/1.1" 200 OK
INFO:     172.17.0.1:45348 - "GET /api/v1/describe HTTP/1.1" 200 OK
tapiab commented 2 years ago

Hi! Could you be more specific on the impacted file and function?

steraite commented 2 years ago

It seems like we loose the host in all the url :

'config': {'KeysNotEqual': {'href': {'actual': 'http://4000/api/v1/config',
                                                 'expected': 'http://localhost:4000/api/v1/config'}}},
'execution': {'KeysNotEqual': {'href': {'actual': 'http://4000/api/v1/process',
                                                       'expected': 'http://localhost:4000/api/v1/process'}}},
'health': {'KeysNotEqual': {'href': {'actual': 'http://4000/api/v1/health',
                                                 'expected': 'http://localhost:4000/api/v1/health'}}},
'self': {'KeysNotEqual': {'href': {'actual': 'http://4000/api/v1/describe',
                                             'expected': 'http://localhost:4000/api/v1/describe'}}},
'version': {'KeysNotEqual': {'href': {'actual': 'http://4000/api/v1/version',
                                                   'expected': 'http://localhost:4000/api/v1/version'}

These are the logs we have when we launch the test pesto/tests/test_service.py from the test test_describe (cf. https://github.com/AirbusDefenceAndSpace/pesto/blob/master/pesto-cli/docs/pesto_test.md)

tapiab commented 2 years ago

Indeed, tnaks for reporting. Sanic is not based on starlette as FastAPI, so the request interface is different. This is fixed here : https://github.com/AirbusDefenceAndSpace/pesto/commit/786645ba0e82a1231c6cf58b626686fa4fdb943e