How to clone echo context?

[kunal-sanghvi]

Issue Description

Using echo an asynchronous web server is developed. It accepts request body synchronously; spawns a go routine to process the request data and concurrently returns 200 OK to client

The flow could be imagined to be as below

1. Request received at web server, echo sends a context c to custom middleware
2. Custom middleware parses the http.Request from echo context c, basically extracting the headers, body, etc
3. Custom middleware populates these details into echo context store by using the c.Set("myKey", "myValue") method
4. At this point --> A go routine is spawned to process this data set inside echo context store --> Return from middleware by setting a static response - c.String(200, "Accepted")
5. Within the handler function, when we try to do c.Get("myKey"), we receive nil for keys set during step 3

Shouldn't we receive myValue during step 5?

We are suspecting the context might be getting Reset here. We are thinking to clone the data inside echo Context c into either a custom context (which implements echo.Context) or maybe use AcquireContext / ReleaseContext utility functions to find a workaround Any suggestions on a safer way to deal with this?

Working code to debug

type AuthData struct {
	Agent string
	TxnID string
}

func createAuthData(c echo.Context) AuthData {
	return AuthData{
		Agent: c.Request().UserAgent(),
		TxnID: c.Request().Header.Get("X-TXN-ID"),
	}
}

func extractionMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		c.Set("myAuthData", createAuthData(c))
		go func() {
			_ = next(c)
		}()
		return c.String(http.StatusOK, "Accepted")
	}
}

func main() {
	router := echo.New()
	router.Use(extractionMiddleware)

	router.GET("/record_stats/", StreamPush)
}

func StreamPush(c echo.Context) error {
	if ad := c.Get("myAuthData"); ad == nil {
		fmt.Print("context is nil")
	} else {
		fmt.Printf("performing further action for %s (%s)", ad.(AuthData).Agent, ad.(AuthData).TxnID)
		// push AuthData to downstream service for processing
	}
	return nil
}

Expected behaviour

In the StreamPush HandlerFunc, we extract AuthData from echo Context and proceed with our further logic to parse the data, which is the else block

Actual behaviour

While most of the times we do not see any issue. But in roughly 2-3% of requests (during high traffic on our platform) we could see the context is nil getting logged

Steps to reproduce

Run some load onto your webserver using vegeta or any other load test tool

Version/commit

v3.3.10

[kunal-sanghvi]

@vishr @lammel could you please take a look at this? Tried a workaround with AcquireContext / ReleaseContext

func extractionMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
                cc := c.Echo().AcquireContext()
                cc.Reset(c.Request().Clone(context.Background()), c.Response().Writer)
	        cc.SetPath(c.Path())
	        cc.SetParamNames(c.ParamNames()...)
	        cc.SetParamValues(c.ParamValues()...)
	        cc.SetHandler(c.Handler())
                cc.Set("myAuthData", createAuthData(cc))
		go func() {
                        defer server.ReleaseContext(cc)
			_ = next(cc)
		}()
		return c.String(http.StatusOK, "Accepted")
	}
}

After I did this I started getting panics in service

net/http.(*conn).serve(0xc000f5c640, 0xc8d600, 0xc000286480)
	/usr/local/go/src/net/http/server.go:2927 +0x38e
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:1890 +0x875
github.com/labstack/echo.(*Echo).ServeHTTP(0xc0001403c0, 0xc8b500, 0xc000fe82a0, 0xc0017b9200)
	/usr/local/go/src/net/http/server.go:2802 +0xa4
	/home/ubuntu/workspace/async_api_refactor/pkg/mod/github.com/labstack/[email protected]+incompatible/router.go:407 +0x11b6
	/usr/local/go/src/runtime/panic.go:679 +0x1b2
panic(0xb180c0, 0xc000deef80)
goroutine 1928 [running]:
github.com/labstack/echo.(*Echo).ServeHTTP.func1(0xca0860, 0xc0002ed810, 0x0, 0xc000459aa0)
github.com/labstack/echo.(*Router).Find(0xc0002ba820, 0xc0003b1540, 0x4, 0xc0003b1545, 0x30, 0xca0860, 0xc0002ed810)
	/usr/local/go/src/net/http/server.go:1767 +0x139
net/http.(*conn).serve.func1(0xc000f5c640)
echo: http: panic serving 127.0.0.1:45688: runtime error: index out of range [1] with length 1
	/home/ubuntu/workspace/async_api_refactor/pkg/mod/github.com/labstack/[email protected]+incompatible/middleware/slash.go:68 +0x132
github.com/labstack/echo/middleware.AddTrailingSlashWithConfig.func1.1(0xca0860, 0xc0002ed810, 0xc0002ed810, 0xc001dbdd70)
	/home/ubuntu/workspace/async_api_refactor/pkg/mod/github.com/labstack/[email protected]+incompatible/echo.go:580 +0x87
net/http.serverHandler.ServeHTTP(0xc00011a620, 0xc8b500, 0xc000fe82a0, 0xc0017b9200)
	/home/ubuntu/workspace/async_api_refactor/pkg/mod/github.com/labstack/[email protected]+incompatible/echo.go:593 +0x222

It looks like empty pvalue list seems to be coming here But why would this happen? a new echo.context is created in memory whenever we call AcquireContext right?

Am I misunderstanding something here?

[pafuent]

Hi @kunal-sanghvi, I guess you are facing an issue that was fixed in a later version than 3.3.10 Here is the PR #1535 Here is the related issue #1492

Besides of that, I think that the correct approach is the one that you showed in your second comment. For all the cases, Echo uses a sync.Pool to manage Context instances. In your first example, the Context could get reused/reset by other request during the use of it in your goroutine. If you make use of Echo#AcquireContext and Echo#ReleaseContext, you still will get Context instances from the same sync.Pool, but you will decide when to put it there again to be reused later (that is done on Echo#ReleaseContext)

[kunal-sanghvi]

Hi @pafuent, we indeed felt the second comment approach would work but instead during peak load times we started seeing panics in our service

But now I'd once try to update to v4.1.17 and check for the same

[pafuent]

@kunal-sanghvi Did you had the opportunity to check if v4.1.17 solved your issue?

[aldas]

You should not pass echo context to other goroutines. Echo context instances are borrowed at the start of serving request and put pack to pool at the end of the request. If you pass it to different goroutine (with different lifetime) you have data race.

For asynchronous endpoints it is cleaner architecture when you extract needed data from request in handler method and use that extracted data to start async process (goroutine) and after starting return httpstatus from handler. In that case you can do some basic input validation and send errors to requester.

architecturally you should not mix transport layer (echo.Context) with you business layer (async process)

[deefdragon]

@aldas while that would likely be Ideal, there is a LOT of important information stored in context. I have a number of async tasks that start after a user hits any number of endpoints, and one of the things that I do is use the context for Logging in those tasks. It allows me to track and log the User and other relevant information even after the main request is done (theoretically).

The issue is that the logging that I am doing is handled by a central library to keep it consistent across services. If I could reasonably just pass the information that I needed, I would. With this central logging however, it becomes basically impossible as I would need to update any number of services after I added something to the central logging. Lets say I started logging request IDs or some new header. I would then have to go to every async request and add that header to the struct of information that I pass in to the async request, Copy that information into the struct, and make sure that the information is then passed into the logging where it needs to be. At this point, I am basically cloning the context already.

TLDR: while getting just the data you need would be ideal, sometimes, you don't known what data you need, so you effectively need all of it just in case.

I am going to create a CloneContext function in my code to return a read only context, but it would be very nice to have that function as part of echo itself.