Log the exception on "Application callable raised an exception" situations

[bluetech]

I am evaluating Granian on a WSGI application, so far it seems very good, thanks for creating it.

I noticed that when an unhandled exception occurs, Granian logs

[WARNING] Application callable raised an exception

but does not log the actual exception info, which makes it hard to debug the issue.

Is it possible to also log the exception traceback?

[nkhitrov]

Same problem with ASGI (FastAPI). No traceback 😞

Maybe it should be error level?

Screen

Granian init

    runtime = Granian(
        "runtime",
        address="0.0.0.0",  # noqa: S104
        port=settings.app_port,
        interface=Interfaces.ASGI,
        loop=Loops.uvloop,
    )

[bluetech]

I took a look and came up with this:

diff --git a/src/wsgi/http.rs b/src/wsgi/http.rs
index cc0b5cc..71b5eb2 100644
--- a/src/wsgi/http.rs
+++ b/src/wsgi/http.rs
@@ -3,6 +3,7 @@ use hyper::{
     Response,
 };
 use std::net::SocketAddr;
+use pyo3::prelude::*;
 
 use super::{
     callbacks::{call_rtb_http, call_rtt_http},
@@ -38,10 +39,20 @@ pub(crate) async fn handle_rtt(
     scheme: &str,
 ) -> HTTPResponse {
     if let Ok(res) = call_rtt_http(callback, Scope::new(scheme, server_addr, client_addr, req).await).await {
-        if let Ok((status, headers, body)) = res {
-            return build_response(status, headers, body);
+        match res {
+            Ok((status, headers, body)) => {
+                return build_response(status, headers, body);
+            }
+            Err(err) => {
+                Python::with_gil(|py| {
+                    if let Some(Ok(traceback)) = err.traceback(py).map(|tb| tb.format()) {
+                        log::warn!("Application callable raised an exception\n{traceback}{err}");
+                    } else {
+                        log::warn!("Application callable raised an exception\n{err}");
+                    }
+                });
+            }
         }
-        log::warn!("Application callable raised an exception");
     } else {
         log::error!("WSGI protocol failure");
     }

This output looks like this:

$ granian --interface wsgi app:app
[INFO] Websockets are not supported on WSGI
[INFO] Starting granian (main PID: 216325)
[INFO] Listening at: 127.0.0.1:8000
[INFO] Spawning worker-1 with pid: 216326
[INFO] Started worker-1
[INFO] Started worker-1 runtime-1
[WARNING] Application callable raised an exception
Traceback (most recent call last):
  File "/home/ran/src/granian/granian/wsgi.py", line 41, in wrapper
    rv = callback(scope.to_environ(dict(basic_env)), resp)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/ran/src/granian/app.py", line 3, in app
    1 / 0
    ~~^~~
ZeroDivisionError: division by zero

However I am unsure if taking the GIL at this location is OK or not. If it is, I can submit a PR with this fix (and similar for ASGI and RSGI).

[gi0baro]

@bluetech acquiring GIL in that section seems good to me. I'll just probably simplify the patch to relay on display method of error, like:

diff --git a/src/wsgi/http.rs b/src/wsgi/http.rs
index cc0b5cc..714cf58 100644
--- a/src/wsgi/http.rs
+++ b/src/wsgi/http.rs
@@ -38,10 +38,17 @@ pub(crate) async fn handle_rtt(
     scheme: &str,
 ) -> HTTPResponse {
     if let Ok(res) = call_rtt_http(callback, Scope::new(scheme, server_addr, client_addr, req).await).await {
-        if let Ok((status, headers, body)) = res {
-            return build_response(status, headers, body);
+        match res {
+            Ok((status, headers, body)) => {
+                return build_response(status, headers, body);
+            },
+            Err(err) => {
+                log::warn!("Application callable raised an exception");
+                pyo3::Python::with_gil(|py| {
+                    err.display(py);
+                });
+            }
         }
-        log::warn!("Application callable raised an exception");
     } else {
         log::error!("WSGI protocol failure");
     }

[bluetech]

@gi0baro err.display prints to stderr, but it should be part of the log::warn, no? Like if the log is configured to output to a file or such (maybe it's not possible now but might in the future).

[gi0baro]

@bluetech you're right, then your code looks appropriate. I would probably rewrite it like this, but I think it's just a matter of personal taste:

diff --git a/src/wsgi/http.rs b/src/wsgi/http.rs
index cc0b5cc..8f78bd2 100644
--- a/src/wsgi/http.rs
+++ b/src/wsgi/http.rs
@@ -38,10 +38,22 @@ pub(crate) async fn handle_rtt(
     scheme: &str,
 ) -> HTTPResponse {
     if let Ok(res) = call_rtt_http(callback, Scope::new(scheme, server_addr, client_addr, req).await).await {
-        if let Ok((status, headers, body)) = res {
-            return build_response(status, headers, body);
+        match res {
+            Ok((status, headers, body)) => {
+                return build_response(status, headers, body);
+            },
+            Err(err) => {
+                let msg = "Application callable raised an exception";
+                let tb = pyo3::Python::with_gil(|py| {
+                    let tb = match err.traceback(py).map(|tb| tb.format()) {
+                        Some(Ok(tb)) => tb,
+                        _ => "".into()
+                    };
+                    format!("{}{}", tb, err)
+                });
+                log::warn!("{}\n{}", msg, tb);
+            }
         }
-        log::warn!("Application callable raised an exception");
     } else {
         log::error!("WSGI protocol failure");
     }