Stack trace not available

[pjebs]

@vishr
We have migrated from negroni to echo.
In Negroni, we had a protect-at-last-resort middleware that caught panics.
In Development mode, that middleware would convert the stack trace and return it using this bit of code:

m := map[string]string{}

stack := make([]byte, 1024*8)
stack = stack[:runtime.Stack(stack, false)]
m["stack"] = fmt.Sprintf("%s", stack)

As a matter of practice we always paniced at the Controller level (but not other inside functions called by out controller) when we wanted to produce an error output as a response.

With Echo, we have created a custom error handler. We do the "echo" way which is to return an error instead of panicing.
This error handler does not seem to be able to retrieve a stacktrace from our request handler functions.
Even when we set runtime.Stack(stack, false) to true, it appears that by the time the custom error handler gets called, the request handler's goroutine has ended.

At this stage, we are thinking of reverting back to using a panic instead of returning errors.
Are we doing something wrong? Can you please give us feedback

[pjebs]

@andizzle @edwardhutchison

[vishr]

@pjebs This came up earlier as well - I think stack trace while logging, as the error is returned and later used to call the HTTP error handler from Echo#ServeHTTP the stack trace for handler is not available - so your understanding is correct. You can look into Recover middleware. Probably to fix it I would move calling http error handler logic into a middleware but I am not sure.

[pjebs]

How about this for a change?

Then request handler looks like this:

func getUser(c echo.Context) error {
  	// User ID from path `users/:id`
  	id := c.Param("id")
	return c.String(http.StatusOK, id)
}

When the request handler returns an error, at the point where the framework collects the returned error, you can record the stack trace and store it somewhere temporarily (such as the echo context) and then we can access it via the customer error handler?

[vishr]

You can't get a stack trace from the returned error. Look into this package https://github.com/go-errors/errors which adds stack trace in the error that you can retrieve in the http error handler. I will update the guide with an example on how to use it.

[pjebs]

I didn't mean getting a stack trace from the error. Rather, when the error is returned, obtaining a stack trace at that point in time.

[vishr]

That will be all internal to the framework, are you interested in that? How does you example output look like?

[pjebs]

Yes I mean a feature request. The framework can add the stack perhaps to echo context for us to access from custom error handler.

[vishr]

I am fine with it but just trying to understand how does stack trace looks like and even how to do it - here is the location https://github.com/labstack/echo/blob/master/echo.go#L583

[andizzle]

@pjebs let's open a PR with a proposed solution.

[andizzle]

The above PR is WIP. It allow us to do something like this in the custom HTTPErrorHandler

func HTTPErrorHandler(err error, c echo.Context) {
        tr := c.Get(echo.TraceContextKey)
        c.JSON(err.Code, tr)
}

It produces the traceback that indicates the DB connection failed to open during the test:

[
    "..."
    "/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:660 +0x62: created by net/http.(*connReader).startBackgroundRead",
    "/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:656 +0xd8: : goroutine 8 [chan receive]:: database/sql.(*DB).connectionOpener(0xc4200872c0)",
    "/usr/local/Cellar/go/1.9.2/libexec/src/database/sql/sql.go:871 +0x53: created by database/sql.Open",
    "/usr/local/Cellar/go/1.9.2/libexec/src/database/sql/sql.go:609 +0x1ee"
]

[vishr]

@andizzle I am not able to understand how capturing stack trace within Echo#ServeHTTP() contains middleware/handler error details. Per your code the stack trace should look something like below:

goroutine 5 [running]:
github.com/labstack/echo.(*Echo).ServeHTTP(0xc420080680, 0x146b5e0, 0xc420114000, 0xc420112000)
	/Users/vr/Projects/labstack/echo/src/github.com/labstack/echo/echo.go:586 +0x2dc
net/http.serverHandler.ServeHTTP(0xc420082ea0, 0x146b5e0, 0xc420114000, 0xc420112000)
	/usr/local/opt/go/libexec/src/net/http/server.go:2619 +0xb4
net/http.(*conn).serve(0xc42009c780, 0x146ba60, 0xc420060280)
	/usr/local/opt/go/libexec/src/net/http/server.go:1801 +0x71d
created by net/http.(*Server).Serve
	/usr/local/opt/go/libexec/src/net/http/server.go:2720 +0x288

[andizzle]

@vishr you are right, the stack trace I was looking at was occured before Echo#ServeHTTP. It's not going to be easy since the middlewares are squashed into a nested function, the error trace on individual middleware calls seems to be ... impossible inside Echo.

@pjebs looks like the we are going to implement this at the middleware level on our own.