Get stacktrace when context.Context is canceled by http.TimeoutHandler

Question

For debugging purposes, how can I get more information on exactly where my http.TimeoutHandler wrapped handler canceled an active http.Request::Context()?

Ideally, a stacktrace should be logged.

Background: The server is set up like this:

    mux := http.NewServeMux()
    mux.Handle("/", http.HandlerFunc(handle_root))

    srv := &http.Server {
        Addr         : fmt.Sprintf("%s:%d", args.address, args.port),
        ReadTimeout  :  2 * time.Second,
        WriteTimeout :  2 * time.Second,
        IdleTimeout  :  2 * time.Second,
        Handler      : http.TimeoutHandler(mux, 1500 * time.Millisecond,
                                           "Backend timeout exceeded"),
    }
    log.Fatal(srv.ListenAndServe())

Where handle_root() calls some helper functions and passes the http.Requests Context() to some database.sql prepared statements QueryContext() calls.

When the timeout is exceeded it would be helpful for debugging/profiling to get some hint on exactly how far the execution proceeded into the handler, e.g. whether it was waiting on the result set of a certain SQL statement or not - and if it was on which one exactly.

Hence, a stacktrace at the point of cancellation should provide this information.

By default, nothing is logged, while my test client receives the expected '503 Service Unavailable/Backend timeout exceeded' reply.

You cannot. Context doesn't provide this feature. You have to do it yourself. When you first detect the timeout locate this position (e.g. via a stacktrace or some sentinel error). — Volker, Feb 25 '23 at 12:02

maxschlepzig · Accepted Answer · 2023-02-27T00:37:39.373

Since context cancellations in context parametrized functions usually result in them returning a non-nil error, dumping the stack on error return also catches timeouts.

They can then be identified by error message text such as:

context deadline exceeded
pq: canceling statement due to user request
http: Handler timeout

As errors are reported via error codes in Go (and not exceptions) and one already has to add error checking boilerplate after each Error returning function call, one can integrate stackdumping there, e.g.:

import (
    // ...
    "runtime/debug"
    // ...
)

func internal_error(w http.ResponseWriter, err error) int {

    log.Printf("ERROR: %s [[[%s]]]", err, debug.Stack())

    status := 500
    w.WriteHeader(status)

    w.Write([]byte(`<html>
    <head><title>Internal Server Error</title></head>
    <body><h1>Internal Server Error (500)</h1></body></html>`))

    return status
}

func handle_something(w http.ResponseWriter, r *http.Request) {

    // ...

    payload, err := select_from_some_table(r.Context(), arg0)
    if err != nil {
        internal_error(w, err)
        return
    }

    // ...

}

In addition, when cancelling SQL statements the database might log such cancelled statements, by default. For example, Postgresql does it like this:

cat /var/lib/pgsql/data/log/postgresql-2023-02-26.log
[..]
2023-02-26 16:51:29.024 UTC [338398] ERROR:  canceling statement due to user request
2023-02-26 16:51:29.024 UTC [338398] STATEMENT:  
            SELECT tt.section, tt.name FROM (
                SELECT DISTINCT section, name FROM ([..]
[..]

Get stacktrace when context.Context is canceled by http.TimeoutHandler

1 Answers1