bug: interaction with SetBodyStreamWriter

[garrettladley]

The Issue

the following config leads to some odd interactions with my streaming fiber handler.

config:

app := fiber.New()
app.Use(slogfiber.NewWithConfig(slog.Default(),
	slogfiber.Config{
		WithRequestID: true,
	},
))

my fiber handler, say GET /foo, uses c.Context().SetBodyStreamWriter(func(w *bufio.Writer)) to stream the response body to the client in chunks.

Response Headers With slogfiber

HTTP/1.1 200 OK
Date: Thu, 02 Jan 2025 01:11:41 GMT
Content-Type: text/event-stream // set by me
Content-Length: 25044 // crux of the issue
X-Request-Id: e8f629e6-d90b-498c-8d0b-f2aa148532ab // from the `WithRequestID: true`
Cache-Control: no-cache // set by me

Transfer-Encoding header missing despite being set with c.Set("Transfer-Encoding", "chunked")

Response Headers Without slogfiber

HTTP/1.1 200 OK
Date: Wed, 01 Jan 2025  01:12:31  GMT
Content-Type: text/event-stream // set by me
Cache-Control: no-cache // set by me
Transfer-Encoding: chunked

Explanation of the Issue

to stream to the client in chunks using theTransfer-Encoding: chunked header, there is one key note:

per the mdn web docs,

The Content-Length header must be omitted

because slogfiber includes response information of the form

{
  "response": {
    "time": "...",
    "latency": 0,
    "status": 200,
    "length": 123 // crux of the issue
  }
}

this call responseAttributes = append(responseAttributes, slog.Int("length", len(c.Response().Body())))

causes the Content-Length: 123 header to be populated, messing up the Transfer-Encoding: chunked header and thus breaking my streaming implementation.

Attempted Workarounds

i tried to add a filter to my config for the impacted streaming route

app := fiber.New()
app.Use(slogfiber.NewWithConfig(slog.Default(),
	slogfiber.Config{
		WithRequestID: true,
		Filters: []slogfiber.Filter{
			slogfiber.IgnorePath("/foo"),
		},
	},
))

however, since the filter check occurs after the problem call (responseAttributes = append(responseAttributes, slog.Int("length", len(c.Response().Body())))), the Content-Length: 123 header is still populated.

SetBodyStreamWriter sets the contentLength to the bodySize of -1, however, slogfiber's call to c.Response().Body() repopulates contentLength, thus the fasthttp.ResponseHeader.SetContentLength func deletes the Transfer-Encoding header

Solution

i can open a pr moving the filter check to the top of the returned handler (middleware), before the potentially problematic calls

[samber]

Hello @garrettladley and thanks for the report.

I agree this should be corrected.

I don't remember why the filter is as far in the code. It must be escaped ASAP in the middleware. i'm going to fix that by myself. (see v1.17.0)

However, I wonder if this middleware should wait for the body to be written before triggering a log record. Either by blocking the middleware chain, or by building the record in a goroutine.

I don't really like the second option, since it might cost a goroutine for each http request. WDYT?

I suppose we can overwrite the body.Close() method and add our own logic.

[garrettladley]

my naive solution would be to add a field to Config

type Config struct {
	// ...
	WithResponseBodyLen   bool
	// ...
}

it would default to true in the New* funcs for backward compatibility, while also allowing toggling of the len check

accompanied with the following change

if config.WithResponseBodyLen {
	responseAttributes = append(responseAttributes, slog.Int("length", len(c.Response().Body())))
}

[zhukovra]

@samber can you update fiber-v3 branch, please?

[samber]

@zhukovra i made an update ✅

[MeowSalty]

Was this issue fixed in v1.18? I seem to be encountering the same problem.

After I used a filter to exclude specific paths, this issue no longer occurs.