otelhttp response writer implementation does not track WriteHeader when Flush is called

[cpuguy83]

Description

When using the otelhttp wrapper to instrument an http endpoint, the wrapper is doing its own tracking to determine if WriteHeader should be called during a Write.

However the wrapper does not implement http.Flusher, as such when Flush() is called on the http.ResponseWriter the undrlying flusher from net/http is called, however otelhttp is not aware that the headers have already been written.
When a subsequent call to Write is made, otelhttp calls WriteHeader first, which has already been called on the underlying net/http implementation, and we wend up with a log printed from net/http:

http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*respWriterWrapper).WriteHeader (wrap.go:98)

Environment

• OS: N/A
• Architecture: N/A
• Go Version: N/A
• otelhttp version: v0.46.1

Steps To Reproduce

Basic example:

func someHandler(w http.ResponseWriter, _ *http.Request) {
  w.(http.Flusher).Flush()
  w.Write([]byte("hello world"))
}

Expected behavior

Since otelhttp is doing its own tracking in its Write implementation for when to call WriteHeader, it needs to be aware of when Flush is called.

[dmathieu]

Could you give us the implementation of your flusher?
In our test suite, if I flush the response writer, then write to it, everything works properly.

opentelemetry-go-contrib/instrumentation/net/http/otelhttp/handler_test.go

Lines 27 to 35 in a91e60b

	name: "implements flusher",
	handler: func(t *testing.T) http.Handler {
	return otelhttp.NewHandler(
	http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	assert.Implements(t, (*http.Flusher)(nil), w)
	}), "test_handler",
	)
	},
	expectedStatusCode: http.StatusOK,

Which makes sense, because the wrapped response writer is a RecorderTest, for which Flush is implemented there:
https://pkg.go.dev/net/http/httptest#ResponseRecorder.Flush

This method will only write the header if it hasn't been written yet (and WriteHeader does the same check).
So when Flush() is called, the header is written. But any further call of WriteHeader is a noop from the main writer.

Should your flusher implementation be doing the same check?

[cpuguy83]

@dmathieu This is the stdlib implementation from a standard net/http.Server

[cpuguy83]

For reference, here is how we fixed this in moby: moby/moby#47796
I do prefer the changes we made to work around this, but still seems like there's a minor issue in the otelhttp implementation.

[dmathieu]

All right, it wasn't happening in tests because the log only happens in the runtime response implementation, not in httptest.
https://cs.opensource.google/go/go/+/refs/tags/go1.22.3:src/net/http/server.go;l=1157

I have opened a fix in #5634.

[cpuguy83]

Thanks for jumping on that!

[Salmonster]

@dmathieu Thanks for making the PR fix for this issue. I'm seeing right now that it has conflicts with the target branch. Do you have an idea of when this will be resolved and a new release issued? A service I work on that has an indirect dependency on go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp is getting this log quite a lot, and I was able to correlate it with http response status 500 errors logged by the same service.

[dmathieu]

Thank you. I have rebased the branch.
Note that this log is a warning though. Removing it will not change any behavior.

As for releases, they happen about once a month.

[lambrospetrou]

It seems that somehow this fix got reverted in some renames...
The current version does not check the w.wroteHeader:

opentelemetry-go-contrib/instrumentation/net/http/otelhttp/internal/request/resp_writer_wrapper.go

Lines 82 to 85 in bb3cf24

	func (w *RespWriterWrapper) Flush() {
	w.WriteHeader(http.StatusOK)
	if f, ok := w.ResponseWriter.(http.Flusher); ok {

The fix that disappeared: 9479910

I just upgraded to v0.54.0 and I am getting hammerred by the header being written multiple times...

time=2024-08-28T22:29:47.275+01:00 level=INFO msg="http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/internal/request.(*RespWriterWrapper).writeHeader (resp_writer_wrapper.go:78)"