services/horizon: Debug "multiple response.WriteHeader calls" errors

[bartekn]

We realized that stdout is not logged in our Horizon cluster (tracking in https://github.com/stellar/puppet-v4/issues/694). After checking it, there were many (usually 4-5 / minute) entries like:

Aug 23 11:03:56 horizon-002c stellar-horizon[16843]: 2019/08/23 11:03:56 http: multiple response.WriteHeader calls

We should find the code responsible and fix it.

[ire-and-curses]

• - determine when this started (use Kibana)
• - decide what the impact is
• - fix if easy or important

[bartekn]

I spent some time today on this issue and I think I understand why it's happening.

I started with finding a correlation between the number of http: multiple response.WriteHeader calls errors in service journal and Horizon HTTP logs. At 14:19:05 UTC there were 8 instances of the error. I checked all responses between 14:19:05 and 14:19:06 UTC sent from the specific server with 8 errors in Kibana: 274 hits. Then I narrowed it down to streaming requests only: 10 hits. From these, 8 took ~55 seconds. 55 seconds is a default request timeout set in Horizon. This is triggered by Timeout middleware of Chi server we are using which I believe is a cause of the errors.

Here's what happens:

1. A new streaming request is sent to Horizon.
2. SSE preamble is sent in WritePreamble that contains: w.WriteHeader(200) call.
3. ...stream is active, 55 seconds pass...
4. Context started in Timeout middleware timeouts and executes another call sending a new header: w.WriteHeader(http.StatusGatewayTimeout).

It seems we already use middleware#WrapResponseWriter middleware in the logger (ex. to get the number of bytes written). We could use it's Status() method to check if the header was already sent. However, it requires creating our own Timeout middleware that makes use of this.

The issue doesn't seem to be critical. We can think more about a fix when more urgent issues are closed in this sprint.

[ire-and-curses]

Awesome sleuthing @bartekn! It's great to see that this is just annoying rather than bad. Agree we can deprioritise. Moved to the bottom of the milestone.

[tamirms]

fixed by #1870

[bartekn]

@jacekn reported new error:

http: superfluous response.WriteHeader call from github.com/go-chi/chi/middleware.(*basicWriter).WriteHeader (wrap_writer.go:74)

in the latest version.