I''m getting the following errors multiple times per request when using 4.3.0. I do not receive any errors when using 4.2.1. Please CC me on replies, I''m not subscribed to the mailing list. 16:48:42 web.1 | E, [2012-04-26T16:48:42.733954 #87940] ERROR -- : app error: Socket is not connected (Errno::ENOTCONN) 16:48:42 web.1 | E, [2012-04-26T16:48:42.734193 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `shutdown'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.734343 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `process_client'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.734517 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:605:in `worker_loop'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.734635 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:487:in `spawn_missing_workers'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.734775 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:137:in `start'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.734946 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/gems/unicorn-4.3.0/bin/unicorn:121:in `<top (required)>'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.735072 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/bin/unicorn:19:in `load'' 16:48:42 web.1 | E, [2012-04-26T16:48:42.735208 #87940] ERROR -- : /Users/jnimety/.rvm/gems/ruby-1.9.3-p125 at control/bin/unicorn:19:in `<main>'' -- Joel Nimety
On Fri, Apr 27, 2012 at 7:36 AM, Joel Nimety <jnimety at continuity.net> wrote:> I''m getting the following errors multiple times per request when using > 4.3.0.I too started noticing these errors. I was trying to do some high level debugging before posting. Here are two examples of what I am getting: cache: [GET /assets/marketing/splash.jpg] stale, valid, store 127.0.0.1 - - [27/Apr/2012 07:50:01] "GET /assets/marketing/splash.jpg HTTP/1.1" 200 30431 0.0411 E, [2012-04-27T07:50:01.636410 #24786] ERROR -- : app error: Socket is not connected (Errno::ENOTCONN) E, [2012-04-27T07:50:01.636556 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `shutdown'' E, [2012-04-27T07:50:01.636664 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `process_client'' E, [2012-04-27T07:50:01.636781 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:605:in `worker_loop'' E, [2012-04-27T07:50:01.636892 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:487:in `spawn_missing_workers'' E, [2012-04-27T07:50:01.636996 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:137:in `start'' E, [2012-04-27T07:50:01.637112 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/bin/unicorn:121:in `<top (required)>'' E, [2012-04-27T07:50:01.637222 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/bin/unicorn:23:in `load'' E, [2012-04-27T07:50:01.637333 #24786] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/bin/unicorn:23:in `<main>'' cache: [GET /assets/marketing/splash-button.gif] stale, valid, store 127.0.0.1 - - [27/Apr/2012 07:50:01] "GET /assets/marketing/splash-button.gif HTTP/1.1" 200 5735 0.0188 cache: [GET /] miss 127.0.0.1 - - [27/Apr/2012 08:03:27] "GET / HTTP/1.1" 200 - 0.7057 E, [2012-04-27T08:03:27.811826 #25138] ERROR -- : app error: Socket is not connected (Errno::ENOTCONN) E, [2012-04-27T08:03:27.811968 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `shutdown'' E, [2012-04-27T08:03:27.812080 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:539:in `process_client'' E, [2012-04-27T08:03:27.812189 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:605:in `worker_loop'' E, [2012-04-27T08:03:27.812301 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:487:in `spawn_missing_workers'' E, [2012-04-27T08:03:27.812411 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/lib/unicorn/http_server.rb:137:in `start'' E, [2012-04-27T08:03:27.812523 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/unicorn-4.3.0/bin/unicorn:121:in `<top (required)>'' E, [2012-04-27T08:03:27.812635 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/bin/unicorn:23:in `load'' E, [2012-04-27T08:03:27.812747 #25138] ERROR -- : /Users/matt/.rbenv/versions/1.9.3-p194/bin/unicorn:23:in `<main>'' cache: [GET /assets/reset.css?body=1] stale, valid, store 127.0.0.1 - - [27/Apr/2012 08:03:28] "GET /assets/reset.css?body=1 HTTP/1.1" 304 - 0.0187 The cache statements are from rack-cache in development. This seems to only be related to static files: images, css, and js assets. The errors change on every request. My application is a 3.2.3 rails app. I can look into this further later in the day. Please let me know if I can provide further debugging information. Thanks! Matt
Joel Nimety <jnimety at continuity.net> wrote:> I''m getting the following errors multiple times per request when using > 4.3.0. I do not receive any errors when using 4.2.1. Please CC me on > replies, I''m not subscribed to the mailing list.Multiple times per request? Yikes. This can be expected occasionally. The below patch will just silently ignore them since they''re not errors we can avoid/deal with any other way. I''d still prefer exceptions to not get raised at all (they''re expensive). Are the rest of you guys getting these errors intermittently, or only once in a while. Rainbows! has long had a similar patch as below, but I''m a bit concerned as to why Joel is getting this multiple times per request...>From 04901da5ae0b4655c83be05d24ae737f1b572002 Mon Sep 17 00:00:00 2001From: Eric Wong <normalperson at yhbt.net> Date: Fri, 27 Apr 2012 11:48:16 -0700 Subject: [PATCH] http_server: ignore ENOTCONN (mostly from shutdown(2)) Since there''s nothing unicorn can do to avoid this error on unconnected/halfway-connected clients, ignoring ENOTCONN is a safe bet. Rainbows! has long had this rescue as it called getpeername(2) on untrusted sockets --- lib/unicorn/http_server.rb | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/unicorn/http_server.rb b/lib/unicorn/http_server.rb index f942e2f..14a6f9a 100644 --- a/lib/unicorn/http_server.rb +++ b/lib/unicorn/http_server.rb @@ -507,7 +507,8 @@ class Unicorn::HttpServer # the socket is closed at the end of this function def handle_error(client, e) msg = case e - when EOFError,Errno::ECONNRESET,Errno::EPIPE,Errno::EINVAL,Errno::EBADF + when EOFError,Errno::ECONNRESET,Errno::EPIPE,Errno::EINVAL,Errno::EBADF, + Errno::ENOTCONN Unicorn::Const::ERROR_500_RESPONSE when Unicorn::RequestURITooLongError Unicorn::Const::ERROR_414_RESPONSE -- Eric Wong
On Fri, Apr 27, 2012 at 2:59 PM, Eric Wong <normalperson at yhbt.net> wrote:> Joel Nimety <jnimety at continuity.net> wrote: >> I''m getting the following errors multiple times per request when using >> 4.3.0. ?I do not receive any errors when using 4.2.1. ?Please CC me on >> replies, I''m not subscribed to the mailing list. > > Multiple times per request? ?Yikes. ?This can be expected occasionally. >46 times in development on the last request I tested. I can provide my Gemfile, logs and any other debug info if you like. Just to reiterate, if I downgrade to 4.2.1 I don''t see the error at all. -- Joel Nimety
Joel Nimety <jnimety at continuity.net> wrote:> On Fri, Apr 27, 2012 at 2:59 PM, Eric Wong <normalperson at yhbt.net> wrote: > > Joel Nimety <jnimety at continuity.net> wrote: > >> I''m getting the following errors multiple times per request when using > >> 4.3.0. ?I do not receive any errors when using 4.2.1. ?Please CC me on > >> replies, I''m not subscribed to the mailing list. > > > > Multiple times per request? ?Yikes. ?This can be expected occasionally. > > 46 times in development on the last request I tested. I can provide > my Gemfile, logs and any other debug info if you like. Just to > reiterate, if I downgrade to 4.2.1 I don''t see the error at all.Yes, the addition of the shutdown() call[1] in 4.3.0 can cause ENOTCONN occasionally. Ignoring the exception works, but given the cost of generating exceptions in Ruby in the first place (especially 1.9), I don''t think it''s a good idea... I can''t reproduce this error. Are you on a UNIX listener or TCP listene? What environment (OS/kernel version) is this? [1] see thread starting here about adding shutdown(): http://mid.gmane.org/CAOG6bOTseAPbjU5LYchODqjdF3-Ez4+M8jo-D_D2Wq0jkdc4Rw at mail.gmail.com
On Fri, Apr 27, 2012 at 11:59 AM, Eric Wong <normalperson at yhbt.net> wrote:> Are the rest of you guys getting these errors intermittently, or only > once in a while. > > Rainbows! has long had a similar patch as below, but I''m a bit concerned > as to why Joel is getting this multiple times per request...I usually get several every request as well (in dev). It can be one or a handful at a time. They seem to be somewhat random as to when they are thrown. Thanks for the patch (and the fantastic support, Eric!). If I can help narrow down the problem please let me know! It seems the issue is when unicorn is serving static files, at least for me. In production, Nginx serves my static files so I doubt there will be any issue. I do have 4.3.0 deployed on Ubuntu 10.04.4 LTS and I just checked the logs and I see no errors when I make the same request.
> Yes, the addition of the shutdown() call[1] in 4.3.0 can cause ENOTCONN > occasionally. > > Ignoring the exception works, but given the cost of generating > exceptions in Ruby in the first place (especially 1.9), I don''t > think it''s a good idea... > > I can''t reproduce this error. ?Are you on a UNIX listener or TCP > listene? ?What environment (OS/kernel version) is this?I am running OS X 10.7.3, ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-darwin11.3.0]. I was going to try it on my linux dev machine in a bit. I can get you kernel version then, if it occurs. I am just running unicorn in local dev and hitting it with a browser (Safari Version 5.1.5 (7534.55.3)) on localhost:8080. In production, I use a UNIX listener. (I am seeing no errors in production.)
> In production, I use a UNIX listener. (I am seeing no errors in production.)(Again unicorn is not serving static files in production.)
On Fri, Apr 27, 2012 at 3:32 PM, Eric Wong <normalperson at yhbt.net> wrote:> Joel Nimety <jnimety at continuity.net> wrote: >> On Fri, Apr 27, 2012 at 2:59 PM, Eric Wong <normalperson at yhbt.net> wrote: >> > Joel Nimety <jnimety at continuity.net> wrote: >> >> I''m getting the following errors multiple times per request when using >> >> 4.3.0. ?I do not receive any errors when using 4.2.1. ?Please CC me on >> >> replies, I''m not subscribed to the mailing list. >> > >> > Multiple times per request? ?Yikes. ?This can be expected occasionally. >> >> 46 times in development on the last request I tested. ?I can provide >> my Gemfile, logs and any other debug info if you like. ?Just to >> reiterate, if I downgrade to 4.2.1 I don''t see the error at all. > > Yes, the addition of the shutdown() call[1] in 4.3.0 can cause ENOTCONN > occasionally. > > Ignoring the exception works, but given the cost of generating > exceptions in Ruby in the first place (especially 1.9), I don''t > think it''s a good idea... > > I can''t reproduce this error. ?Are you on a UNIX listener or TCP > listene? ?What environment (OS/kernel version) is this?OS X 10.7.3, ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-darwin11.3.0] with the latest command line x code. tcp, using the the following config. I''ve tried removing preload_app but it didn''t help. listen 3000 worker_processes 4 preload_app true timeout 30> > > [1] see thread starting here about adding shutdown(): > ?http://mid.gmane.org/CAOG6bOTseAPbjU5LYchODqjdF3-Ez4+M8jo-D_D2Wq0jkdc4Rw at mail.gmail.com-- Joel Nimety SVP Technology Continuity Control 203.285.8133 (office) 203.763.9263 (cell) http://www.continuity.net http://www.linkedin.com/in/jnimety
George <lists at SouthernOhio.net> wrote:> Just fyi, my dev logs are now rife with these: http://j.mp/IezMAu > > Will plug your patch in, but will have to figure out another option for > heroku deployment.Is this affecting your heroku deployment? What OS/kernel version are you running? From what Joel and Matt say, it could be more likely to trigger on *BSD-based systems.
Eric Wong <normalperson at yhbt.net> wrote:> George <lists at SouthernOhio.net> wrote: > > Just fyi, my dev logs are now rife with these: http://j.mp/IezMAu > > > > Will plug your patch in, but will have to figure out another option for > > heroku deployment. > > Is this affecting your heroku deployment? What OS/kernel version > are you running? From what Joel and Matt say, it could be more likely > to trigger on *BSD-based systems.Also, if you revert my previous patch, does this also prevent the error from manifesting? (I expect ignoring ENOTCONN _once_in_a_while_ will be required, but definitely not every request). diff --git a/lib/unicorn/http_server.rb b/lib/unicorn/http_server.rb index 14a6f9a..bb91e7f 100644 --- a/lib/unicorn/http_server.rb +++ b/lib/unicorn/http_server.rb @@ -537,7 +537,7 @@ class Unicorn::HttpServer end @request.headers? or headers = nil http_response_write(client, status, headers, body) - client.shutdown # in case of fork() in Rack app + client.close_write # in case of fork() in Rack app client.close # flush and uncork socket immediately, no keepalive rescue => e handle_error(client, e)
On Fri, Apr 27, 2012 at 12:51 PM, Eric Wong <normalperson at yhbt.net> wrote:> George <lists at SouthernOhio.net> wrote: >> Just fyi, my dev logs are now rife with these: http://j.mp/IezMAu >> >> Will plug your patch in, but will have to figure out another option for >> heroku deployment. > > Is this affecting your heroku deployment? ?What OS/kernel version > are you running? ?From what Joel and Matt say, it could be more likely > to trigger on *BSD-based systems.I just tried on a 64-bit Ubuntu 11.10 (kernel 3.0.0-17-generic), ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]. No issue. Reloaded a several pages, many times. No ENOTCONN. Not one. Same app. Neither on ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-linux]. BSD issue?
Matt Smith <matt at nearapogee.com> wrote:> I just tried on a 64-bit Ubuntu 11.10 (kernel 3.0.0-17-generic), ruby > 1.9.3p0 (2011-10-30 revision 33570) [x86_64-linux]. No issue. Reloaded > a several pages, many times. No ENOTCONN. Not one. Same app.OK, thank you for the confirmation. I wouldn''t rule out an occasional ENOTCONN, though, even if nginx <-> unicorn are on the same LAN. So I''ll still push out my change to ignore Errno::ENOTCONN. Since it''s highly uncommon in production environments, I''m not concerned about the performance overhead.> BSD issue?It doesn''t affect my FreeBSD 9.0 nor Debian/kFreeBSD 6.0 VMs, either. OSX is non-Free Software, so unicorn cannot officially support it and performance is irrelevant on it.
George <lists at SouthernOhio.net> wrote:> No, you know I think you''re right Eric. I am testing on OS X 10.7.4 prior > to deployment at the moment and so it appears that the bsd core has some > bearing here.It might just be OSX, I can''t reproduce the issue on FreeBSD 9.0 nor Debian/kFreeBSD 6.0. Any OpenBSD/NetBSD users care to chime in?> I''m also curious, have you considered switching over to GitHub for issue > management? I''m spoiled nowadays with issue reporting vs the good old > mailing lists. Even Google''s mailing lists are a step above. ;)No. I can''t stand web browsers and logging into websites. I''ll never endorse commercial interests when working on Free Software, either. Usenet would be ideal, but it''s mostly dead nowadays but everybody still has email (more or less, HTML mail isn''t appropriate for *nix-based development) For mailing lists, consider a proper Unix MUA with threading support[1] an essential part of your development environment (as important as your $EDITOR). With Unix pipes, messages flow between inbox/working directory easily (via tools like patch/git-am). This also lets me use the same $EDITOR for both writing code and emails. [1] - mutt in my case, but I''ve heard good things about alpine and GNUS
> For mailing lists, consider a proper Unix MUA with threading support[1] > an essential part of your development environment (as important as your > $EDITOR). ?With Unix pipes, messages flow between inbox/working > directory easily (via tools like patch/git-am). ?This also lets me use > the same $EDITOR for both writing code and emails.I keep meaning to make the transition to mutt... Thanks for the reminder. ;-)