Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix superfluous response.WriteHeader call #47715

Draft
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

krissetto
Copy link
Contributor

Fixes #47448

- What I did
Edited the endpoints for container stats and logs to avoid superfluous response.WriteHeader call being logged by the stdlib because we call WriteHeader() too many times.

- How I did it
Writing the response headers manually for streaming response writers instead of calling Flush().

OTEL instrumentation doesn't seem to wrap the Flush() func of http.ResponseWriter, so if we call Flush() on ioutils.WriteFlusher we directly hit the underlying stdlib implementation of Write()/WriteHeader() instead of the OTEL wrapped one.
If we then call Write() on the OTEL wrapper, after manually calling Flush() from ioutils, the wrapper will not know that headers have been written already and will therefore call the stdlib WriteHeaders() again, causing the warning log

- How to verify it

- Description for the changelog

Fixes the `superfluous response.WriteHeader call` warning log when executing `docker logs ...` or `docker compose stats`.

- A picture of a cute animal (not mandatory but encouraged)

api/server/httputils/write_log_stream.go Show resolved Hide resolved
// Used instead of the Flush() we had previously, so we don't set the header twice because of the otel wrapper
// see here: https://github.com/moby/moby/issues/47448
if rw, ok := w.(http.ResponseWriter); ok {
rw.WriteHeader(http.StatusOK)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Trying to figure out how writing this here would prevent OTEL from trying to write a header again; wouldn't it still hit the "already wrote header" case?

func (w *respWriterWrapper) WriteHeader(statusCode int) {
if !w.wroteHeader {
w.wroteHeader = true
w.statusCode = statusCode
}
w.ResponseWriter.WriteHeader(statusCode)
}

Copy link
Contributor Author

@krissetto krissetto Apr 15, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Trying to figure out how writing this here would prevent OTEL from trying to write a header again; wouldn't it still hit the "already wrote header" case?

func (w *respWriterWrapper) WriteHeader(statusCode int) {
if !w.wroteHeader {
w.wroteHeader = true
w.statusCode = statusCode
}
w.ResponseWriter.WriteHeader(statusCode)
}

Our Flusher calls Flush() on the stdlib implementation, not on the OTEL wrapper because it doesn't wrap the Flush() func. WriteHeader(), so if we call this here we are setting w.wroteHeader to true on the OTEL wrapper, so that subsequent calls to the OTEL wrapper's Write() func will NOT call the OTEL wrapper's WriteHeader() func.


example of current sitation:

calls to flusher.Flush();

  • stdlib Flush() gets called by flusher.Flush();
  • stdlib Write() gets called by stdlib Flush();
  • stdlib WriteHeader() gets called by stdlibWrite()

calls to flusher.Write():

  • OTEL wrapper Write() gets called by flusher.Write();
  • OTEL wrapper WriteHeader() gets called by OTEL wrapper Write() - only when it hasn't been called before;
  • stdlib WriteHeader() gets called by OTEL wrapper WriteHeader();
  • stdlib Write() gets called by OTEL wrapper Write();
  • flusher.Flush() gets called by flusher.Write();
  • ... repeat above flow

Sorry for the verbosity, too much wrapping confusion here :)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems like we either to need to manually instrument the streaming responses or provide a smarter writer implementation to the daemon so that the first flush calls WriteHeader explicitly.

…Flush()

Signed-off-by: Christopher Petito <47751006+krissetto@users.noreply.github.com>
@laurazard
Copy link
Member

This seems like the cleanest/least-hacky fix for this, thanks!

@laurazard laurazard added the kind/bugfix PR's that fix bugs label Apr 15, 2024
@laurazard laurazard requested a review from cpuguy83 April 15, 2024 13:51
@laurazard laurazard added this to the 26.1.0 milestone Apr 15, 2024
// Used before the Flush(), so we don't set the header twice because of the otel wrapper
// see here: https://github.com/moby/moby/issues/47448
if rw, ok := outStream.(http.ResponseWriter); ok {
rw.WriteHeader(http.StatusOK)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not the right place to handle this.

I'm also not sure how this fix the otel issue since the very first write to the stream would be writing out the response header.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not the right place to handle this.
...
It seems like we either to need to manually instrument the streaming responses or provide a smarter writer implementation to the daemon so that the first flush calls WriteHeader explicitly.

Yeah i mostly agree with this, but there's another couple things to consider here:

I have opened another draft pr yesterday, moving the current WriteFlusher impl and making a new internal one in /internal/writeflusher with these changes.

If we merge that, this PR can be closed as it'd be unnecessary, but I left it here in case we decide on a different strategy and we only want a quick fix for now.

// Used instead of the Flush() we had previously, so we don't set the header twice because of the otel wrapper
// see here: https://github.com/moby/moby/issues/47448
if rw, ok := w.(http.ResponseWriter); ok {
rw.WriteHeader(http.StatusOK)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems like we either to need to manually instrument the streaming responses or provide a smarter writer implementation to the daemon so that the first flush calls WriteHeader explicitly.

@vvoland vvoland modified the milestones: 26.1.0, 27.0.0, 26.1.1 Apr 19, 2024
@vvoland vvoland modified the milestones: 26.1.1, 26.1.2 Apr 30, 2024
@vvoland vvoland modified the milestones: 26.1.2, 26.1.3 May 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bugfix PR's that fix bugs
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Syslog entry: "superfluous response.WriteHeader call" in Docker 25.x
5 participants