Discussion: How best to catch and log 500s?

[ssoroka]

What I would like

I would like 5xx error messages go to the logs and non-descriptive errors back to the requestor. It's potentially a security issue for 5xx errors to go back to the requestor as this may leak internal system information, or even secrets

What I do now

I actually have a work-around to the question in the title. I use middleware to capture the response body (custom context) and if the status is 5xx, I spit the response body out to the logs, though this doesn't alleviate the problem of returning too much information to the requestor.

potential solution

My recommendation would be to change it so that all huma.StatusError 5xx and other unhandled errors are instead logged (or there is a handler to attach a logger), and a standard Internal Server Error type response is used (appropriate to the status code). If we are trying to give a good user experience, we could maybe give each error a unique identifier and then also pass it to the logs/error-callback-handler-thing

thoughts?

[danielgtaylor]

@ssoroka I think a middleware is the correct approach here, as you have mentioned you already do. You can capture and log the response, and replace the body as needed. You could also use a transformer to detect errors with a 5xx status and rewrite e.g. the description of error details fields.

I've mostly avoided default / built-in logging of requests/responses as this requires additional buffering in memory and should probably be optional due to the performance ramifications, but I'm open to ideas here!

[tpoterba]

Chiming in that I'm trying to create exactly the same outcome and having trouble. I think right now it's not possible to capture the error from the response in middleware without buffering, since huma takes the error (already in memory) and writes it to the connection buffer directly. I'd love a way to pull the error out more cheaply.

Thanks for your hard work on this great library, Daniel!

[ssoroka]

Yeah, I'll second this. because by the time the middleware gets the response it's already been written to the body buffer, you have to wrap the middleware in a fake context that captures the output.
It's not trivial; I'll share my implementation here so you get a sense of the hoops you have to jump through to do this:

type humaContext huma.Context

type deadlineWriter interface {
	SetWriteDeadline(time.Time) error
}

type statusAwareContext struct {
	humaContext
	status     int
	bodyWriter io.Writer
}

func (c *statusAwareContext) SetStatus(status int) {
	c.status = status
	c.humaContext.SetStatus(status)
}

func (c *statusAwareContext) Body() string {
	if c.bodyWriter == nil {
		return ""
	}
	return c.bodyWriter.(*bytes.Buffer).String()
}

type writerWrapper struct {
	io.Writer
	c *statusAwareContext
}

func (ww writerWrapper) SetWriteDeadline(t time.Time) error {
	if w, ok := ww.c.humaContext.BodyWriter().(deadlineWriter); ok {
		return w.SetWriteDeadline(t)
	}
	return nil
}

func (ww writerWrapper) Flush() {
	if f, ok := ww.c.humaContext.BodyWriter().(http.Flusher); ok {
		f.Flush()
	}
}

func (c *statusAwareContext) BodyWriter() io.Writer {
	if c.bodyWriter == nil {
		c.bodyWriter = bytes.NewBuffer(nil)
	}
	return writerWrapper{Writer: io.MultiWriter(c.humaContext.BodyWriter(), c.bodyWriter), c: c}
}

func logRequestMiddleware(ctx huma.Context, next func(huma.Context)) {
	log.Printf("Request started: %s %s", ctx.Method(), ctx.Operation().Path)
	start := time.Now()
	myCtx := &statusAwareContext{humaContext: ctx}
	next(myCtx)
	log.Printf("Request: %s %s - %d %s", ctx.Method(), ctx.Operation().Path, myCtx.status, time.Since(start))
	if myCtx.status >= 400 {
		log.Printf("Error Response body: %s", myCtx.Body())
	}
}

Thoughts are:

• I should be able to log all 500s by default, since they're app errors. An erroring app logs nothing by default (!? - surprising)
  • If you're trying to keep the app agnostic of logging, huma should allow attaching a callback for when an unhandled error gets returned from a handler (allowing attaching logging).
• 500s with error details shouldn't be returned to the requestor, only a generic "Internal Server Error", to avoid leaking internal information on error. State-of-the-art here is returning an error code that references a code in the logs that someone can look up.
  • at the very least I should be able to suppress this "500 raw errors get sent to client" behavior without rewriting the response body, which has worse performance implications (I need extra buffers of every response in memory)