Bug 55114 - Errors (tracebacks) are not logged anymore
Summary: Errors (tracebacks) are not logged anymore
Status: CLOSED FIXED
Alias: None
Product: UCS@school
Classification: Unclassified
Component: HTTP-API (Kelvin)
Version: UCS@school 5.0
Hardware: Other Linux
: P5 normal
Target Milestone: ---
Assignee: Daniel Tröder
QA Contact: Carlos García-Mauriño
URL: https://git.knut.univention.de/univen...
Keywords:
Depends on:
Blocks:
 
Reported: 2022-08-18 01:57 CEST by Jürn Brodersen
Modified: 2023-01-30 13:32 CET (History)
2 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 5: Major Usability: Impairs usability in key scenarios
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 5: Blocking further progress on the daily work
User Pain: 0.286
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Customer ID:
Max CVSS v3 score:


Attachments
possible kelvin error log fix (584 bytes, patch)
2022-08-18 01:57 CEST, Jürn Brodersen
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Jürn Brodersen univentionstaff 2022-08-18 01:57:21 CEST
Created attachment 10975 [details]
possible kelvin error log fix

Errors (tracebacks) are not logged anymore

For some reason only the 500 http error is logged but no traceback. That worked in the past. I'm not sure why it stopped working? I was able to get tracebacks back, by setting the log file explicitly. See the attached patch.

How to reproduce:
- Add an exception to one of the kelvin resources
- Call the resource
- Check /var/log/univention/ucsschool-kelvin-rest-api/http.log for a 500 error without a traceback
Comment 1 Daniel Tröder univentionstaff 2022-08-18 08:00:07 CEST
In 2019 I removed the root logger from getting written to disk. It was catching to much unrelated logs from all libraries. But that's to far in the past I guess...

In version 0.18 uvicorn made a few changes to its logging. Maybe they moved certain messages from uvicorn.access to uvicron.error or changes the severity?
Comment 3 Daniel Tröder univentionstaff 2023-01-16 11:27:45 CET
I think the problem is simply, that the unhandled_exception_handler() just adds the correlation ID, but does not log the error. This would probably fix it:

diff --git kelvin-api/ucsschool/kelvin/main.py kelvin-api/ucsschool/kelvin/main.py
index 377b9834..7f54c3ec 100644
--- kelvin-api/ucsschool/kelvin/main.py
+++ kelvin-api/ucsschool/kelvin/main.py
@@ -148,6 +148,7 @@ async def udm_exception_handler(request: Request, exc: UdmError) -> JSONResponse
 @app.exception_handler(Exception)
 async def unhandled_exception_handler(request: Request, exc: Exception) -> JSONResponse:
     """Add Correlation-ID to HTTP 500."""
+    logger.exception(f"While responding to {request.method!s} {request.url!r}: {exc!s}")
     return await http_exception_handler(
         request,
         HTTPException(
Comment 5 Tobias Wenzel univentionstaff 2023-01-24 10:15:42 CET
has been qa't by carlos and merged already and will be released with 1.8.3
Comment 6 Tobias Wenzel univentionstaff 2023-01-30 13:32:22 CET
has just been released with 1.8.3