Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Parent context unexpectedly expires with child #30287

Closed
inliquid opened this issue Feb 18, 2019 · 4 comments
Closed

Parent context unexpectedly expires with child #30287

inliquid opened this issue Feb 18, 2019 · 4 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@inliquid
Copy link

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
Copy link
Member

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!

@odeke-em odeke-em added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Feb 18, 2019
@inliquid
Copy link
Author

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
Copy link
Member

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
screen shot 2019-02-18 at 1 15 04 pm

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
Copy link
Author

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

@golang golang locked and limited conversation to collaborators Feb 18, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

3 participants