nginx reverse proxy getting ECONNRESET

nginx reverse proxy getting ECONNRESET

[Michael Fischer]

We have an nginx 1.6.2 proxy in front of a Unicorn 4.8.3 server that
is frequently reporting the following error:

2015/03/24 01:46:01 [error] 11217#0: *872231 readv() failed (104:
Connection reset by peer) while reading upstream

The interesting things are:

1) The upstream is a Unix domain socket (to which Unicorn is bound)
2) Unicorn isn't reporting that a child died in the error log (and I
verified their lifetimes with ps(1))

Any hints as to what we should look for?

Thanks,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Michael Fischer <mfischer@zendesk.com> wrote:
> We have an nginx 1.6.2 proxy in front of a Unicorn 4.8.3 server that
> is frequently reporting the following error:
> 
> 2015/03/24 01:46:01 [error] 11217#0: *872231 readv() failed (104:
> Connection reset by peer) while reading upstream
> 
> The interesting things are:
> 
> 1) The upstream is a Unix domain socket (to which Unicorn is bound)
> 2) Unicorn isn't reporting that a child died in the error log (and I
> verified their lifetimes with ps(1))
> 
> Any hints as to what we should look for?

What changed recently with your setup?

Which OS/kernel version + vendor version?

Since you've been around a while, I take it this is only a recent issue?

Can you setup a test instance on a different nginx port/unicorn socket
and with a config.ru such as:

------------------------- 8< ----------------------
run(lambda do |env|
  $stderr.write("#$$ starting at #{Time.now}\n")
  # be sure to configure your unicorn timeout
  sleep
  # should not return, wait for unicorn to kill
end)
----------------------------------------------------

And hitting nginx with a single test request to reproduce the issue.

And see if it happens on the same/different hosts where you notice the
problem.

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Another likely explanation might be you're not draining rack.input every
request, since unicorn does lazy reads off the socket to prevent
rejected uploads from wasting disk I/O[1]

So you can send a bigger POST request with my example to maybe
reproduce the issue.

[1] you can use the Unicorn::PrereadInput middleware to forcibly
    disable the lazy read:
    http://unicorn.bogomips.org/Unicorn/PrereadInput.html

Re: nginx reverse proxy getting ECONNRESET

[Michael Fischer]

On Tue, Mar 24, 2015 at 10:54 PM, Eric Wong <e@80x24.org> wrote:
> Michael Fischer <mfischer@zendesk.com> wrote:
>> We have an nginx 1.6.2 proxy in front of a Unicorn 4.8.3 server that
>> is frequently reporting the following error:
>>
>> 2015/03/24 01:46:01 [error] 11217#0: *872231 readv() failed (104:
>> Connection reset by peer) while reading upstream
>>
>> The interesting things are:
>>
>> 1) The upstream is a Unix domain socket (to which Unicorn is bound)
>> 2) Unicorn isn't reporting that a child died in the error log (and I
>> verified their lifetimes with ps(1))
>>
>> Any hints as to what we should look for?
>
> What changed recently with your setup?

We upgraded nginx from 1.4.7 to 1.6.2.  The frequency of the error has
increased significantly since.  But I hesitate to point the finger at
nginx without more evidence, since its developers are very skilled.

> Which OS/kernel version + vendor version?

uname -3.13.0-40-generic #69~precise1-Ubuntu

Ruby 2.1.1

> Can you setup a test instance on a different nginx port/unicorn socket
> and with a config.ru such as:
>
> ------------------------- 8< ----------------------
> run(lambda do |env|
>   $stderr.write("#$$ starting at #{Time.now}\n")
>   # be sure to configure your unicorn timeout
>   sleep
>   # should not return, wait for unicorn to kill
> end)
> ----------------------------------------------------
>
> And hitting nginx with a single test request to reproduce the issue.

I'll take that step later if I have to, but I'm not sure what evidence
that would provide, since we're not having timeout issues -- when this
happens, the response time reported by nginx is usually just a few
seconds (Unicorn timeout is 90 seconds),

Thanks,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Michael Fischer]

On Tue, Mar 24, 2015 at 10:59 PM, Eric Wong <e@80x24.org> wrote:
> Another likely explanation might be you're not draining rack.input every
> request, since unicorn does lazy reads off the socket to prevent
> rejected uploads from wasting disk I/O[1]
>
> So you can send a bigger POST request with my example to maybe
> reproduce the issue.
>
> [1] you can use the Unicorn::PrereadInput middleware to forcibly
>     disable the lazy read:
>     http://unicorn.bogomips.org/Unicorn/PrereadInput.html

Actually, these are quite large POST requests we're attempting to
service (on the order of 4MB).  Can you elaborate on the mechanism in
play here?

Thanks,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Michael Fischer <mfischer@zendesk.com> wrote:
> On Tue, Mar 24, 2015 at 10:59 PM, Eric Wong <e@80x24.org> wrote:
> > Another likely explanation might be you're not draining rack.input every
> > request, since unicorn does lazy reads off the socket to prevent
> > rejected uploads from wasting disk I/O[1]
> >
> > So you can send a bigger POST request with my example to maybe
> > reproduce the issue.
> >
> > [1] you can use the Unicorn::PrereadInput middleware to forcibly
> >     disable the lazy read:
> >     http://unicorn.bogomips.org/Unicorn/PrereadInput.html
> 
> Actually, these are quite large POST requests we're attempting to
> service (on the order of 4MB).  Can you elaborate on the mechanism in
> play here?

Unlike a lot of servers, unicorn will not attempt to buffer request
bodies on its own.  You'll need to actually process the POST request in
your app (via Rack/Rails/whatever accessing env["rack.input"]).

The PrereadInput middleware makes it behave like other servers
(at the cost of being slower if a request is worthless and rejected)

So there might be data sitting on the socket if your application
processing returns a response before it parsed the POST request.

In this case, the ECONNRESET messages are harmless and saves your
Ruby process from GC thrashing.

Actually, you can try setting up a Rack::Lobster instance but sending
a giant POST request?

------------- config.ru --------------
require 'rack/lobster'
run Rack::Lobster.new
--------------------------------------

Re: nginx reverse proxy getting ECONNRESET

[Michael Fischer]

On Tue, Mar 24, 2015 at 11:23 PM, Eric Wong <e@80x24.org> wrote:

> So there might be data sitting on the socket if your application
> processing returns a response before it parsed the POST request.

When this occurs, the nginx access logs show an HTTP 200 (OK) response
with a 0 byte response body.

Is it your hypothesis that the application is just failing to consume
the entire POST body in this instance?   In that case, wouldn't we
expect to see nginx failing to write on the socket instead of read?

> Actually, you can try setting up a Rack::Lobster instance but sending
> a giant POST request?
>
> ------------- config.ru --------------
> require 'rack/lobster'
> run Rack::Lobster.new
> --------------------------------------

I don't know what this is -- systems guy here, not a Rack expert...
how will this help?

Thanks,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Michael Fischer <mfischer@zendesk.com> wrote:
> On Tue, Mar 24, 2015 at 11:23 PM, Eric Wong <e@80x24.org> wrote:
> 
> > So there might be data sitting on the socket if your application
> > processing returns a response before it parsed the POST request.
> 
> When this occurs, the nginx access logs show an HTTP 200 (OK) response
> with a 0 byte response body.
> 
> Is it your hypothesis that the application is just failing to consume
> the entire POST body in this instance?   In that case, wouldn't we
> expect to see nginx failing to write on the socket instead of read?

It could've been just big enough to fit inside the kernel socket
buffers, but not enough for nginx to wait on.  In the below standalone
example, the server only reads 4092 bytes of the 4096-byte request.

> > Actually, you can try setting up a Rack::Lobster instance but sending
> > a giant POST request?
> >
> > ------------- config.ru --------------
> > require 'rack/lobster'
> > run Rack::Lobster.new
> > --------------------------------------
> 
> I don't know what this is -- systems guy here, not a Rack expert...
> how will this help?

Just a dumb "hello world" type app which doesn't read the input.

Here's a bare-bones example without nginx/unicorn at all:

require 'tmpdir'
require 'socket'
Dir.mktmpdir do |dir|
  Dir.chdir(dir) do
    path = 'sock'
    a = UNIXServer.new(path)
    srv = Thread.new do
      c = a.accept
      c.readpartial(4092)
      c.write 'HTTP/1.1 200 OK\r\n\r\n'
      c.close
      puts "thread done"
    end

    con = UNIXSocket.new(path)
    bytes = ' ' * 4096
    con.write(bytes)
    while buf = con.sysread(4096)
      p [ 'client read' , buf ]
    end
  end
end

The above causes sysread to fail with ECONNRESET in the server.  If you
change the above server to read 4096 bytes instead of 4092, and you get
the expected EOFError instead.

ECONNRESET is harmless in this case (unless nginx started pipelining or
blindly attempting persistent connections to unicorn, which it should
not be doing since unicorn sends "Connection: close" on every response)

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Eric Wong <e@80x24.org> wrote:
> ECONNRESET is harmless in this case (unless nginx started pipelining or
> blindly attempting persistent connections to unicorn, which it should
> not be doing since unicorn sends "Connection: close" on every response)

Actually, are you getting 502 errors returned from nginx in this case?
That would not be harmless.  I suggest ensuring rack.input is
fully-drained if that is the case (perhaps using PrereadInput).

Re: nginx reverse proxy getting ECONNRESET

[Michael Fischer]

On Tue, Mar 24, 2015 at 11:55 PM, Eric Wong <e@80x24.org> wrote:

> Actually, are you getting 502 errors returned from nginx in this case?
> That would not be harmless.  I suggest ensuring rack.input is
> fully-drained if that is the case (perhaps using PrereadInput).

No, they're all 200 responses with a zero-length body size.  It's the
first time I'd ever seen such a combination of symptoms.

Thanks,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Michael Fischer]

On Tue, Mar 24, 2015 at 11:46 PM, Eric Wong <e@80x24.org> wrote:

>> Is it your hypothesis that the application is just failing to consume
>> the entire POST body in this instance?   In that case, wouldn't we
>> expect to see nginx failing to write on the socket instead of read?
>
> It could've been just big enough to fit inside the kernel socket
> buffers, but not enough for nginx to wait on.  In the below standalone
> example, the server only reads 4092 bytes of the 4096-byte request.

> Here's a bare-bones example without nginx/unicorn at all:

[snip]

Thank you for the example; it really zeroes in on the situation.  I
learn something new every day!

I'll check with the developers to find out whether the app is
misbehaving in a similar way.

Best regards,

--Michael

Re: nginx reverse proxy getting ECONNRESET

[Eric Wong]

Michael Fischer <mfischer@zendesk.com> wrote:
> On Tue, Mar 24, 2015 at 11:55 PM, Eric Wong <e@80x24.org> wrote:
> 
> > Actually, are you getting 502 errors returned from nginx in this case?
> > That would not be harmless.  I suggest ensuring rack.input is
> > fully-drained if that is the case (perhaps using PrereadInput).
> 
> No, they're all 200 responses with a zero-length body size.  It's the
> first time I'd ever seen such a combination of symptoms.

OK, thanks for the update.

I was wondering if including a Unicorn::PostreadInput middleware should
be introduced to quiet your logs.  It should have the same effect as
PrereadInput, but should provide better performance in the common case
and also be compatible with "rewindable_input false" users.

class Unicorn::PostreadInput
  def initialize(app)
    @app = app
  end

  def call(env)
    input = env["rack.input"] # save it here, in case the app reassigns it
    @app.call(env)
  ensure
    # Ensure the HTTP request is entirely read off the socket even
    # if the app aborts early.  This should prevent nginx from
    # complaining about ECONNRESET errors.
    unless env["rack.hijack_io"]
      buf = ''
      true while input.read(16384, buf)
      buf.clear
    end
  end
end

(totally untested)

"Postread" doesn't sound quite right, though...

Re: nginx reverse proxy getting ECONNRESET

[Gabe Martin-Dempesy]

Follow up on the resolution.

Data was being left in the socket, although it wasn’t immediately obvious why. The affected end point received gzipped POST bodies, and would process this somewhat like this:

    uncompressed_body = StringIO.new(Zlib::GzipReader.new(request.body).read)
    process(uncompressed_body)

At the end of each request, all of the uncompressed data had been consumed and `uncompressed_body.eof?` would always be true. However, GzipReader#close wasn’t explicitly called, causing anywhere between 1 and 7 trailing bytes of the 8 byte gzip footer to remain unread in request.body (rack.input) in a small portion of requests. Rewriting this to explicitly close the GzipReader forces it to read and validate the footer, and leaves us with a completely consumed request.body.

Thanks for your help identifying the root cause.