Verbessertes Logging #64

Brain · 2022-01-26T23:49:04+01:00

Brain commented

2022-01-26 23:49:04 +01:00

Dieser PR sorgt einerseits dafür, dass im production-Modus Logs ausgegeben werden. Gleichzeitig wird ein einheitliches Format für Zeitstempel eingeführt, um das Debugging zu erleichtern.

[2022-01-26 23:34:11,497] INFO in app: Hello from KI
[2022-01-26 23:34:11,582] INFO [alembic.runtime.migration] Context impl SQLiteImpl.
[2022-01-26 23:34:11,582] INFO [alembic.runtime.migration] Will assume non-transactional DDL.
[2022-01-26 23:34:11,593] INFO [waitress] Serving on http://0.0.0.0:5000
[2022-01-26 23:34:17,093] ERROR in auth: ldap connection failed

Zentrale Ursache für das Problem in production war, dass die alembic-Config sämtliche Logger neu konfiguriert hat. Da in dieser Config nichts anderes gesetzt war (und eine leere Logging-Config nicht geht), habe ich die ganze alembic.ini entfernt.

Manche Libraries loggen über den Flask-Logger, andere über einen eigenen, der dann zum root-Logger hoch-bubbled. Um keine Log-Ausgaben zu verpassen, muss also der root-Logger auch einsatzbereit sein. Entsprechend musste für einzelne Logger propagate auf False gesetzt werden, um Dopplungen zu vermeiden.

Fixes kompetenzinventar/ki-doku#27
Fixes kompetenzinventar/ki-doku#42

Dieser PR sorgt einerseits dafür, dass im production-Modus Logs ausgegeben werden. Gleichzeitig wird ein einheitliches Format für Zeitstempel eingeführt, um das Debugging zu erleichtern. ``` [2022-01-26 23:34:11,497] INFO in app: Hello from KI [2022-01-26 23:34:11,582] INFO [alembic.runtime.migration] Context impl SQLiteImpl. [2022-01-26 23:34:11,582] INFO [alembic.runtime.migration] Will assume non-transactional DDL. [2022-01-26 23:34:11,593] INFO [waitress] Serving on http://0.0.0.0:5000 [2022-01-26 23:34:17,093] ERROR in auth: ldap connection failed ``` Zentrale Ursache für das Problem in production war, dass die alembic-Config sämtliche Logger neu konfiguriert hat. Da in dieser Config nichts anderes gesetzt war (und eine leere Logging-Config nicht geht), habe ich die ganze alembic.ini entfernt. Manche Libraries loggen über den Flask-Logger, andere über einen eigenen, der dann zum root-Logger hoch-bubbled. Um keine Log-Ausgaben zu verpassen, muss also der root-Logger auch einsatzbereit sein. Entsprechend musste für einzelne Logger propagate auf False gesetzt werden, um Dopplungen zu vermeiden. Fixes kompetenzinventar/ki-doku#27 Fixes kompetenzinventar/ki-doku#42

👍 1

Brain added 5 commits 2022-01-26 23:49:05 +01:00

19aebcc327

Use app logger instead of root logger

689a5ba33e

Keep alembic from configuring loggers

1360b4c738

Give the root logger a nicer format

695c88e159

Prevent duplicate log entries

f7e058d387

Get rid of more duplicate logging

weeman reviewed 2022-01-27 08:03:11 +01:00

app.py

													
				@ -27,0 +24,4 @@

				app.logger.propagate = False # do not forward messages to the root logger

				logging.basicConfig(level=loglevel, format='[%(asctime)s] %(levelname)s [%(name)s] %(message)s') # configure root logger as fallback

				logging.getLogger('werkzeug').propagate = False # werkzeug has its own ColorStreamHandler

				set_library_log_detail_level(BASIC) # ldap3 has different verbosity levels internally

weeman commented

2022-01-27 08:03:11 +01:00

Wäre es eine Idee das hier auf das höchste zu setzen, wenn der KI_LOGLEVEL z.B. <= DEBUG ist?
Also kein abgefahrenes Mapping sondern nur eine Stufe und fertig.
Wir hatten ja schon Probleme mit dem LDAP.

Wäre es eine Idee das hier auf das höchste zu setzen, wenn der `KI_LOGLEVEL` z.B. `<= DEBUG` ist? Also kein abgefahrenes Mapping sondern nur eine Stufe und fertig. Wir hatten ja schon Probleme mit dem LDAP.

Brain commented

2022-01-27 14:06:23 +01:00

Gewissermaßen passiert das schon. ldap3 selbst loggt im Standard nur, wenn der root-Logger auf DEBUG steht.

Gleichermaßen bedeutet das, dass ldap3 in production nie selbst loggen wird. Das könnte ich aber noch einbauen. Also wenn production, dann soll ldap3 loggen, aber auf Level ERROR statt BASIC.

BASIC ist schon einigermaßen noisy. Die detaillierteren Level gehen dann auf Netzwerk- und Protokollebene, was für den normalen Entwicklungsalltag zu viel sein dürfte. Die sollten vielleicht nur konkret bei der Fehlersuche eingesetzt werden.

Gewissermaßen passiert das schon. _ldap3_ selbst loggt im Standard nur, wenn der root-Logger auf `DEBUG` steht. Gleichermaßen bedeutet das, dass _ldap3_ in production nie selbst loggen wird. Das könnte ich aber noch einbauen. Also wenn production, dann soll _ldap3_ loggen, aber auf Level `ERROR` statt `BASIC`. `BASIC` ist schon einigermaßen noisy. Die detaillierteren Level gehen dann auf Netzwerk- und Protokollebene, was für den normalen Entwicklungsalltag zu viel sein dürfte. Die sollten vielleicht nur konkret bei der Fehlersuche eingesetzt werden.