-3

I'm getting this error sporadically on Heroku:

Proxy service:

Dec 27 14:53:05 betalo-turnpike-production app/web.2:  { [...] } 

Dec 27 14:53:08 my-proxy app/web.2:  {
    "level":"error",
    "ts":"2018-12-27T14:53:07.771Z",
    "caller":"httputil/reverseproxy.go:393","msg":"http: proxy error: read tcp [REDACTED]->[REDACTED]: i/o timeout",
    "stacktrace":"log.(*Logger).Output

    /app/tmp/cache/go1.11.4/go/src/log/log.go:172
log.(*Logger).Printf
    /app/tmp/cache/go1.11.4/go/src/log/log.go:179
net/http/httputil.(*ReverseProxy).logf
    /app/tmp/cache/go1.11.4/go/src/net/http/httputil/reverseproxy.go:393
net/http/httputil.(*ReverseProxy).defaultErrorHandler
    /app/tmp/cache/go1.11.4/go/src/net/http/httputil/reverseproxy.go:158
net/http/httputil.(*ReverseProxy).defaultErrorHandler-fm
    /app/tmp/cache/go1.11.4/go/src/net/http/httputil/reverseproxy.go:166
net/http/httputil.(*ReverseProxy).ServeHTTP
    /app/tmp/cache/go1.11.4/go/src/net/http/httputil/reverseproxy.go:234
net/http/httputil.(*ReverseProxy).ServeHTTP-fm
    [...]
net/http.HandlerFunc.ServeHTTP
    /app/tmp/cache/go1.11.4/go/src/net/http/server.go:1964
net/http.serverHandler.ServeHTTP
    /app/tmp/cache/go1.11.4/go/src/net/http/server.go:2741
net/http.(*conn).serve
    /app/tmp/cache/go1.11.4/go/src/net/http/server.go:1847"} 

Dec 27 14:53:08 my-proxy app/web.2:  { [...] "status":502} 

Dec 27 14:53:09 my-proxy heroku/router:  sock=backend at=error code=H18 desc="Server Request Interrupted" [...] dyno=web.2 connect=0ms service=4453ms status=503 protocol=https

Called service:

Dec 27 14:53:05 my-service app/web.1:  { [...] } 
Dec 27 14:53:08 my-service app/web.1:  { [...] "status":400} 
Dec 27 14:53:08 my-service heroku/router:  sock=client at=warning code=H27 desc="Client Request Interrupted" [...] dyno=web.1 connect=1ms service=2995ms status=499 bytes=0 protocol=https

Anyone knows what is wrong?

Harald Nordgren
  • 11,693
  • 6
  • 41
  • 65
  • 2
    *Questions seeking debugging help ("why isn't this code working?") must include the desired behavior, a specific problem or error and **the shortest code necessary to reproduce it** in the question itself.* See [Minimal, Complete, Verifiable Example](https://stackoverflow.com/help/mcve) on SO Help. – Adrian Dec 27 '18 at 20:43

1 Answers1

1

externally, my proxy returns 502 (upstream gone away) my proxy talks to my service which returns 400 (client error) the router layer returns 499 (client closed request)

what is happening is that the external caller is dropping the connection while the "my service" is preparing a result to go back on the connection to "my proxy". This means that the socket drops from the "my proxy" side.

The router at the my service side logs a 499 and so the app logs a 400

There is nothing wrong with your code. The external clients using your web service are dropping their connections early and this is how the application responds in logs

Vorsprung
  • 32,923
  • 5
  • 39
  • 63
  • Thanks for you comment! I'm starting to realize that the client dropping the request is normalish behavior, so it's up to the server to be able to handle that gracefully. What irks me is the amount of different (loggable) ways that my proxy seems to be able to fail on this: `context canceled`, `net/http: request canceled`, `unexpected EOF` and `http: proxy error: read tcp [...]->[...]: i/o timeout`. Are you seeing similar behaviors? Maybe this simply represent different points in time that a request was canceled. – Harald Nordgren Dec 28 '18 at 01:25
  • I've seen this problem on a completely different type of system to heroku. The question is how does the frontend respond to the external client going away? If the frontend drops the connection to the backend then this sequence of response codes will happen. Often, these errors do not matter – Vorsprung Dec 28 '18 at 08:15