Parent context unexpectedly expires with child

[inliquid]

I'm using context with net/http.Request. Recently I made a mistake:

ctx, cancel := context.WithTimeout(r.Context(), timeout)
defer cancel()
<...>
next.ServeHTTP(w, r) // <-- child context has not been passed

So here is something missing, either
next.ServeHTTP(w, r.WithContext(ctx)) or
r = r.WithContext(ctx)

However, what I found is that it doesn't change anything. So in called handler I can run this code:

select {
    <...>
    case <-r.Context().Done():
    fmt.Println("Parent context expired?")
    <...>
}

and see this message as output.

Parent context expired?

[odeke-em]

Hello @inliquid, thanks for filing this bug!

Unfortunately I still can't tell what your bug is about -- could you please provide a minimal reproducible bug to help articulate the problem? Thank you!

[inliquid]

Hi, here is example:

package main

import (
	"context"
	"log"
	"net/http"
	"time"
)

const (
	contextTimeout = 3 * time.Second
	handlerTimeout = 5 * time.Second
)

func main() {
	listenAddr := "127.0.0.1:8080"
	log.Printf("Server is listening on [%s]...\n", listenAddr)

	http.Handle("/", middleware(sleep))
	log.Fatalln(http.ListenAndServe(listenAddr, nil))
}

func middleware(next http.HandlerFunc) http.HandlerFunc {
	return func(w http.ResponseWriter, r *http.Request) {
		ctx, _ := context.WithTimeout(r.Context(), contextTimeout)

		go next.ServeHTTP(w, r) // <-- passing parent context (r) instead of child (r.WithContext(ctx))

		<-ctx.Done()
	}
}

func sleep(w http.ResponseWriter, r *http.Request) {
	log.Println("Got request")

	timer := time.NewTimer(handlerTimeout)
	defer timer.Stop()

	select {
	case <-timer.C:
		log.Println("Timer expired")
	case <-r.Context().Done():
		log.Println("Context expired")
	}
}

In case contextTimeout < handlerTimeout this will output smth like:

2019/02/18 17:36:54 Server is listening on [127.0.0.1:8080]...
2019/02/18 17:36:58 Got request
2019/02/18 17:37:01 Context expired

Not sure if this is by design, but seems that child context becomes expired automatically when any handler, holding r, no matter with which context, returns. Note that in the example middleware doesn't have deferred call of CancelFunc.

From the other hand this behavior, if by design, is not documented at all, neither in (*context) Done nor in (*context) Err:

    // Done returns a channel that's closed when work done on behalf of this
    // context should be canceled. Done may return nil if this context can
    // never be canceled. Successive calls to Done return the same value.
    //
    // WithCancel arranges for Done to be closed when cancel is called;
    // WithDeadline arranges for Done to be closed when the deadline
    // expires; WithTimeout arranges for Done to be closed when the timeout
    // elapses.
    //
    // Done is provided for use in select statements:
    //
    //  // Stream generates values with DoSomething and sends them to out
    //  // until DoSomething returns an error or ctx.Done is closed.
    //  func Stream(ctx context.Context, out chan<- Value) error {
    //  	for {
    //  		v, err := DoSomething(ctx)
    //  		if err != nil {
    //  			return err
    //  		}
    //  		select {
    //  		case <-ctx.Done():
    //  			return ctx.Err()
    //  		case out <- v:
    //  		}
    //  	}
    //  }
    //
    // See https://blog.golang.org/pipelines for more examples of how to use
    // a Done channel for cancelation.
    Done() <-chan struct{}

    // If Done is not yet closed, Err returns nil.
    // If Done is closed, Err returns a non-nil error explaining why:
    // Canceled if the context was canceled
    // or DeadlineExceeded if the context's deadline passed.
    // After Err returns a non-nil error, successive calls to Err return the same error.
    Err() error

[odeke-em]

Thanks for posting the detailed code update @inliquid!

So when ServeHTTP returns, the context bound to the incoming request expires and this is documented in https://golang.org/pkg/net/http/#Request.Context

What's basically happening is that in your middleware call, you wait for at least 3 seconds to expire until <-ctx.Done() returns but then since go next.ServeHTTP(w, r) was invoked and starts at some point in the future, the subsequent select of 5s vs when ServeHTTP(w, r) will select on r.Context().Done() since the entire Handler.ServeHTTP returned and its context got cancelled.

Thus, this isn't a bug and the context of a request out-living its serving would cause unintended and inconsistency problems e.g. when a client disconnects it could create goroutine leaks (goroutines whose termination isn't known nor deterministic hence linger past their determined) thus not freeing up resources when the initiating request returns.

If you'd like to spawn background work, please derive a new context and also perhaps make sure that your ServeHTTP calls return deterministically instead of <-ctx.Done() being outlived by go next.ServeHTTP(w, r) -- perhaps add the goroutine in the contents of your next.ServeHTTP

[inliquid]

@odeke-em I see, thank you for explanation. Now it makes sense.