Add backend logging configuration

[florimondmanca]

Closes #186

TODO:

• Tester sur staging

Cette PR configure le serveur backend pour afficher les logs en format "humain" dans la console en développement, et en JSON en production (plus facile à éventuellement traiter).

$ make serve-server
[server] 2022-06-27 17:10:07,744 INFO:     uvicorn.error: Will watch for changes in these directories: ['/home/florimond/dev/prj-catalogue/catalogage-donnees/server']
[server] 2022-06-27 17:10:07,745 INFO:     uvicorn.error: Uvicorn running on http://localhost:3579 (Press CTRL+C to quit)
[server] 2022-06-27 17:10:07,758 INFO:     uvicorn.error: Started reloader process [146526] using watchgod
[server] 2022-06-27 17:10:08,393 INFO:     uvicorn.error: Started server process [146561]
[server] 2022-06-27 17:10:08,393 INFO:     uvicorn.error: Waiting for application startup.
[server] 2022-06-27 17:10:08,393 INFO:     uvicorn.error: Application startup complete.
[server] 2022-06-27 17:10:20,550 INFO:     uvicorn.access: 127.0.0.1:54132 - "GET /docs HTTP/1.1" 200
[server] 2022-06-27 17:10:20,680 INFO:     uvicorn.access: 127.0.0.1:54132 - "GET /openapi.json HTTP/1.1" 200

$ APP_SERVER_MODE=live make serve-server
./tools/colorize_prefix.sh [server] 34 "venv/bin/python -m server.main"
[server] {"asctime": "2022-06-27 17:18:14,388", "levelname": "INFO", "name": "uvicorn.error", "message": "Started server process [148892]"}
[server] {"asctime": "2022-06-27 17:18:14,388", "levelname": "INFO", "name": "uvicorn.error", "message": "Waiting for application startup."}
[server] {"asctime": "2022-06-27 17:18:14,388", "levelname": "INFO", "name": "uvicorn.error", "message": "Application startup complete."}
[server] {"asctime": "2022-06-27 17:18:14,389", "levelname": "INFO", "name": "uvicorn.error", "message": "Uvicorn running on http://localhost:3579 (Press CTRL+C to quit)"}
[server] {"asctime": "2022-06-27 17:18:30,292", "levelname": "INFO", "name": "uvicorn.access", "message": "127.0.0.1:54134 - \"GET /api/docs HTTP/1.1\" 404"}

Une fois mergé, on pourra ajouter nos propres logs (utile pour le debugging) avec:

import logging

logger = logging.getLogger(__name__)

logger.debug("This is a debug line...")
logger.debug("Another debug line", extra={"value": "Some extra value"})

Références qui m'ont servi :

• FastAPI Uvicorn logging in production
• Add example of logging config file encode/uvicorn#491 (comment)

[florimondmanca]

Validation staging

J'ai déployé puis inspecté les fichiers de logs.

/var/log/server.out.log : le nouveau format JSON est utilisé

$ tail /var/log/server.out.log
INFO:     86.247.59.154:0 - "GET /datasets/?page_number=1&page_size=50&q= HTTP/1.0" 200 OK
INFO:     86.247.59.154:0 - "GET /datasets/filters/ HTTP/1.0" 422 Unprocessable Entity
INFO:     86.247.59.154:0 - "GET /datasets/?page_number=1&page_size=50&q= HTTP/1.0" 200 OK
INFO:     86.247.59.154:0 - "GET /auth/check/ HTTP/1.0" 200 OK
{"asctime": "2022-06-30 10:36:39,682", "levelname": "INFO", "name": "uvicorn.error", "message": "Started server process [2978686]"}
{"asctime": "2022-06-30 10:36:39,682", "levelname": "INFO", "name": "uvicorn.error", "message": "Waiting for application startup."}
{"asctime": "2022-06-30 10:36:39,683", "levelname": "INFO", "name": "uvicorn.error", "message": "Application startup complete."}
{"asctime": "2022-06-30 10:36:39,686", "levelname": "INFO", "name": "uvicorn.error", "message": "Uvicorn running on http://localhost:3579 (Press CTRL+C to quit)"}

/var/log/server.err.log : on voit l'ancien format de logs pour l'arrêt du serveur (suite au redémarrage lié au déploiement), mais pas les nouveaux logs pour le démarrage du serveur : c'est attendu, car tout le logging est dirigé vers stdout. On voit les logs de démarrage ci-dessus.

$ tail /var/log/server.err.log
sqlalchemy.exc.InterfaceError: (sqlalchemy.dialects.postgresql.asyncpg.InterfaceError) <class 'asyncpg.exceptions._base.InterfaceError'>: connection is closed
[SQL: SELECT "user".id, "user".email, "user".password_hash, "user".role, "user".api_token 
FROM "user" 
WHERE "user".api_token = %s]
[parameters: ('038e69079a0e4a5adfc57e6aac79eca696db77ec3eb02fb527fb821f52ab64cb',)]
(Background on this error at: https://sqlalche.me/e/14/rvf5)
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [2931886]