"upstream timed out" after upgrades

"upstream timed out" after upgrades

[John-Paul Bader]

Hey guys,


i recently updated several components of my website setup: 

varnish   2.0.5 -> 2.0.6
nginx      7.4.2 -> 7.4.5
unicorn  0.95.3 -> 0.96
ruby18  to the latest patch level 
and rails from 2.3.2

It all seemed to work great but recently I noticed that the website hangs loading. The weird thing is that it hangs because 2 or 3 javascript files take about a minute to finish and when they do they are incomplete as in cut of in the middle of the content. The nginx error log gives the following output every few seconds:

2010/02/04 08:58:41 [error] 29389#0: *471 upstream timed out (60: Operation timed out) while reading upstream, client: 213.73.89.122, server: www.ccc.de, request: "GET /javascripts/jquery-1.3.2.min.js?1246657683 HTTP/1.1", upstream: "http://unix:/var/run/unicorn.sock:/javascripts/jquery-1.3.2.min.js?1246657683", host: "www.ccc.de"

I don't think its varnishs fault because i get Internal Server Errors (500) if I run curl on the machine against nginx, not at first though - several requests for that jquery file run just fine and then suddenly i get a 500 on a request with the content being cut of in the middle.

Next thing I did was configuring unicorn to listen on 213.73.89.122:9090 rather than on a socket so i could run curl directly against it and even after a fresh start of unicorn gives me:


curl http://213.73.89.122:9090/javascripts/jquery-1.3.2.min.js
(lots of javascript)…,rowspan:"rowSpan",tabindex:"tabIndHTTP/1.1 500 Internal Server Error

curl: (18) transfer closed with 16256 bytes remaining to read

I also downgraded back to 0.95.3 but that didn't change anything. So now after 8h of try and error I'm out of ideas and would be happy to hear some suggestions.

Kind regards, John
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Hrm its getting weirder and weirder.

I started unicorn_rails now manually in the app root which is now running on rails 2.3.3 again: 

sudo unicorn_rails -E production -d -c /usr/local/etc/unicorn.rb

Now first of all it throws lots of Exceptions it couldn't find several (important) gems and then it produces this every second or so:

Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)

When I request the javascript in question I get:

Exception `Errno::EINVAL' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn/http_response.rb:67 - Invalid argument
Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)

This is the same no matter if I run it with -c or not. 

I am puzzled.

To give you the entire output of unicorn starting:

[hukl@cccms /usr/local/www/cccms]$ sudo unicorn_rails -E production -d -p 9090
{:daemonize=>false,
 :unicorn_options=>{:listeners=>["0.0.0.0:9090"]},
 :app=>
  #<Proc:0x0000000801782388@/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/bin/unicorn_rails:124>}
Exception `Errno::EEXIST' at /usr/local/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/cache
Exception `Errno::EEXIST' at /usr/local/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/pids
Exception `Errno::EEXIST' at /usr/local/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/sessions
Exception `Errno::EEXIST' at /usr/local/lib/ruby/1.8/fileutils.rb:243 - File exists - tmp/sockets
I, [2010-02-04T09:42:08.141034 #38499]  INFO -- : listening on addr=213.73.89.122:9090 fd=3
Exception `LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- Win32API
Exception `LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:38 - no such file to load -- Win32API
I, [2010-02-04T09:42:08.158275 #38499]  INFO -- : worker=0 spawning...
I, [2010-02-04T09:42:08.159352 #38499]  INFO -- : master process ready
I, [2010-02-04T09:42:08.159471 #38501]  INFO -- : worker=0 spawned pid=38501
I, [2010-02-04T09:42:08.197082 #38501]  INFO -- : Refreshing Gem list
Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem builder (~> 2.1.2)

Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem memcache-client (>= 1.7.4)

Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem tzinfo (~> 0.3.12)

Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem i18n (~> 0.1.3)

Exception `TypeError' at (eval):4 - can't modify frozen object
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- fast_xs
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- json
Using c extension for JSON.
Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem tmail (~> 1.2.3)

Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- tmail/tmailscanner
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:38 - no such file to load -- tmail/tmailscanner
Exception `MissingSourceFile' at /usr/local/lib/ruby/gems/1.8/gems/activesupport-2.3.3/lib/active_support/dependencies.rb:162 - no such file to load -- tmail/tmailscanner
Exception `Gem::LoadError' at /usr/local/lib/ruby/site_ruby/1.8/rubygems.rb:827 - Could not find RubyGem activerecord-postgresql-adapter (>= 0)

Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- pg
WARNING: Nokogiri was built against LibXML version 2.7.3, but has dynamically loaded 2.7.6
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- ruby-debug
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- classtree
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:38 - no such file to load -- classtree
Exception `MissingSourceFile' at /usr/local/lib/ruby/gems/1.8/gems/activesupport-2.3.3/lib/active_support/dependencies.rb:162 - no such file to load -- classtree
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31 - no such file to load -- methodsig
Exception `MissingSourceFile' at /usr/local/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:38 - no such file to load -- methodsig
Exception `MissingSourceFile' at /usr/local/lib/ruby/gems/1.8/gems/activesupport-2.3.3/lib/active_support/dependencies.rb:162 - no such file to load -- methodsig
=> Debugger enabled
worker=0 ready
Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)
Exception `Errno::EINVAL' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn/http_response.rb:67 - Invalid argument
Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)
Exception `Errno::EINVAL' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn/http_response.rb:67 - Invalid argument
Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)
Exception `Errno::EINVAL' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn/http_response.rb:67 - Invalid argument
Exception `Errno::EAGAIN' at /usr/local/lib/ruby/gems/1.8/gems/unicorn-0.95.3/lib/unicorn.rb:640 - Resource temporarily unavailable - accept(2)


I seriously have no idea went wrong - It ran all so smooth couple of days ago. What am I missing - there must be something plain wrong. I left the js files out of the public site for now - it isn't needed that much and its more important to serve the content for now. In case you are trying to get it.

Kind regards, John


On 04.02.2010, at 09:16, John-Paul Bader wrote:

> Hey guys,
> 
> 
> i recently updated several components of my website setup: 
> 
> varnish   2.0.5 -> 2.0.6
> nginx      7.4.2 -> 7.4.5
> unicorn  0.95.3 -> 0.96
> ruby18  to the latest patch level 
> and rails from 2.3.2
> 
> It all seemed to work great but recently I noticed that the website hangs loading. The weird thing is that it hangs because 2 or 3 javascript files take about a minute to finish and when they do they are incomplete as in cut of in the middle of the content. The nginx error log gives the following output every few seconds:
> 
> 2010/02/04 08:58:41 [error] 29389#0: *471 upstream timed out (60: Operation timed out) while reading upstream, client: 213.73.89.122, server: www.ccc.de, request: "GET /javascripts/jquery-1.3.2.min.js?1246657683 HTTP/1.1", upstream: "http://unix:/var/run/unicorn.sock:/javascripts/jquery-1.3.2.min.js?1246657683", host: "www.ccc.de"
> 
> I don't think its varnishs fault because i get Internal Server Errors (500) if I run curl on the machine against nginx, not at first though - several requests for that jquery file run just fine and then suddenly i get a 500 on a request with the content being cut of in the middle.
> 
> Next thing I did was configuring unicorn to listen on 213.73.89.122:9090 rather than on a socket so i could run curl directly against it and even after a fresh start of unicorn gives me:
> 
> 
> curl http://213.73.89.122:9090/javascripts/jquery-1.3.2.min.js
> (lots of javascript)…,rowspan:"rowSpan",tabindex:"tabIndHTTP/1.1 500 Internal Server Error
> 
> curl: (18) transfer closed with 16256 bytes remaining to read
> 
> I also downgraded back to 0.95.3 but that didn't change anything. So now after 8h of try and error I'm out of ideas and would be happy to hear some suggestions.
> 
> Kind regards, John
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

One more,

I reproduced the upgrading on my staging server which was still at the old state in terms of software. I started by upgrading ruby from

ruby+nopthreads-1.8.7.160_5,1       -> ruby+nopthreads-1.8.7.248,1
ruby18-iconv-1.8.7.160,1                   -> ruby18-iconv-1.8.7.248,1

And voilá - the very same problems. So now I'm like what?

Is this rather a ruby than a unicorn issue ? Couldn't find any clues in the changelog so far: http://svn.ruby-lang.org/cgi-bin/viewvc.cgi/tags/v1_8_7_248/ChangeLog

Kind regards, John
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@h3q.com> wrote:
> One more,

Hi,

About the exceptions, looks like you had '-d' (debug) instead of '-D'
(daemonize) so it spewed every exception (even if trapped) to stderr.
EAGAIN is common when dealing with non-blocking sockets.  Most of that
is noise...

However the EINVAL in unicorn/http_response.rb is suspect.

> I reproduced the upgrading on my staging server which was still at the
> old state in terms of software. I started by upgrading ruby from
> 
> ruby+nopthreads-1.8.7.160_5,1       -> ruby+nopthreads-1.8.7.248,1
> ruby18-iconv-1.8.7.160,1                   -> ruby18-iconv-1.8.7.248,1
> 
> And voilá - the very same problems. So now I'm like what?
> 
> Is this rather a ruby than a unicorn issue ? Couldn't find any clues
> in the changelog so far:
> http://svn.ruby-lang.org/cgi-bin/viewvc.cgi/tags/v1_8_7_248/ChangeLog

That should narrow it down, so I start reading diffs from
v1_8_7_160..v1_8_7_248 ...

Does backporting the following change in ruby_1_8
(but not yet in the ruby_1_8_7 branch) fix things for you?

commit 841a57341ed43f5fa86489c12aceb25a232be820
Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
Date:   Fri Jan 8 09:51:23 2010 +0000

    * io.c (io_fwrite): preserve errno.  [ruby-core:27425]
    
    
    git-svn-id: http://svn.ruby-lang.org/repos/ruby/branches/ruby_1_8@26253

  (snipped)

diff --git a/io.c b/io.c
index 375cbc8..d4d28e5 100644
--- a/io.c
+++ b/io.c
@@ -122,6 +122,9 @@ extern void Init_File _((void));
 # endif
 #endif
 
+#define preserving_errno(stmts) \
+	do {int saved_errno = errno; stmts; errno = saved_errno;} while (0)
+
 VALUE rb_cIO;
 VALUE rb_eEOFError;
 VALUE rb_eIOError;
@@ -490,7 +493,7 @@ io_fwrite(str, fptr)
 	r = write(fileno(f), RSTRING(str)->ptr+offset, l);
         TRAP_END;
 #if BSD_STDIO
-	fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET);
+	preserving_errno(fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET));
 #endif
         if (r == n) return len;
         if (0 <= r) {
---
Of course, the original reason for this fseeko() was to fix another
problem Unicorn exposed when mixing stdio + unistd calls...

   http://redmine.ruby-lang.org/issues/show/2267

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Hey again,

I will try to compile build the svn revision and let you know. I have to do some other work before that so I will report back in the evening (CEST / BERLIN) 

Thank you for helping out, kind regards,

John

On 04.02.2010, at 11:11, Eric Wong wrote:

> John-Paul Bader <hukl@h3q.com> wrote:
>> One more,
> 
> Hi,
> 
> About the exceptions, looks like you had '-d' (debug) instead of '-D'
> (daemonize) so it spewed every exception (even if trapped) to stderr.
> EAGAIN is common when dealing with non-blocking sockets.  Most of that
> is noise...
> 
> However the EINVAL in unicorn/http_response.rb is suspect.
> 
>> I reproduced the upgrading on my staging server which was still at the
>> old state in terms of software. I started by upgrading ruby from
>> 
>> ruby+nopthreads-1.8.7.160_5,1       -> ruby+nopthreads-1.8.7.248,1
>> ruby18-iconv-1.8.7.160,1                   -> ruby18-iconv-1.8.7.248,1
>> 
>> And voilá - the very same problems. So now I'm like what?
>> 
>> Is this rather a ruby than a unicorn issue ? Couldn't find any clues
>> in the changelog so far:
>> http://svn.ruby-lang.org/cgi-bin/viewvc.cgi/tags/v1_8_7_248/ChangeLog
> 
> That should narrow it down, so I start reading diffs from
> v1_8_7_160..v1_8_7_248 ...
> 
> Does backporting the following change in ruby_1_8
> (but not yet in the ruby_1_8_7 branch) fix things for you?
> 
> commit 841a57341ed43f5fa86489c12aceb25a232be820
> Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
> Date:   Fri Jan 8 09:51:23 2010 +0000
> 
>    * io.c (io_fwrite): preserve errno.  [ruby-core:27425]
> 
> 
>    git-svn-id: http://svn.ruby-lang.org/repos/ruby/branches/ruby_1_8@26253
> 
>  (snipped)
> 
> diff --git a/io.c b/io.c
> index 375cbc8..d4d28e5 100644
> --- a/io.c
> +++ b/io.c
> @@ -122,6 +122,9 @@ extern void Init_File _((void));
> # endif
> #endif
> 
> +#define preserving_errno(stmts) \
> +	do {int saved_errno = errno; stmts; errno = saved_errno;} while (0)
> +
> VALUE rb_cIO;
> VALUE rb_eEOFError;
> VALUE rb_eIOError;
> @@ -490,7 +493,7 @@ io_fwrite(str, fptr)
> 	r = write(fileno(f), RSTRING(str)->ptr+offset, l);
>         TRAP_END;
> #if BSD_STDIO
> -	fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET);
> +	preserving_errno(fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET));
> #endif
>         if (r == n) return len;
>         if (0 <= r) {
> ---
> Of course, the original reason for this fseeko() was to fix another
> problem Unicorn exposed when mixing stdio + unistd calls...
> 
>   http://redmine.ruby-lang.org/issues/show/2267
> 
> -- 
> Eric Wong
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Hey,

i checked out the revision 26253 built it and ran it and it seems to work again but: I didn't build it via FreeBSD ports so there might be a difference in configure / build options and I checked out the revision which included the change you suspect for causing the issue so I'm not sure if thats really helping us. Curling directly unicorn works without truncation and issues though.

Kind regards, John

On 04.02.2010, at 13:26, John-Paul Bader wrote:

> Hey again,
> 
> I will try to compile build the svn revision and let you know. I have to do some other work before that so I will report back in the evening (CEST / BERLIN) 
> 
> Thank you for helping out, kind regards,
> 
> John
> 
> On 04.02.2010, at 11:11, Eric Wong wrote:
> 
>> John-Paul Bader <hukl@h3q.com> wrote:
>>> One more,
>> 
>> Hi,
>> 
>> About the exceptions, looks like you had '-d' (debug) instead of '-D'
>> (daemonize) so it spewed every exception (even if trapped) to stderr.
>> EAGAIN is common when dealing with non-blocking sockets.  Most of that
>> is noise...
>> 
>> However the EINVAL in unicorn/http_response.rb is suspect.
>> 
>>> I reproduced the upgrading on my staging server which was still at the
>>> old state in terms of software. I started by upgrading ruby from
>>> 
>>> ruby+nopthreads-1.8.7.160_5,1       -> ruby+nopthreads-1.8.7.248,1
>>> ruby18-iconv-1.8.7.160,1                   -> ruby18-iconv-1.8.7.248,1
>>> 
>>> And voilá - the very same problems. So now I'm like what?
>>> 
>>> Is this rather a ruby than a unicorn issue ? Couldn't find any clues
>>> in the changelog so far:
>>> http://svn.ruby-lang.org/cgi-bin/viewvc.cgi/tags/v1_8_7_248/ChangeLog
>> 
>> That should narrow it down, so I start reading diffs from
>> v1_8_7_160..v1_8_7_248 ...
>> 
>> Does backporting the following change in ruby_1_8
>> (but not yet in the ruby_1_8_7 branch) fix things for you?
>> 
>> commit 841a57341ed43f5fa86489c12aceb25a232be820
>> Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
>> Date:   Fri Jan 8 09:51:23 2010 +0000
>> 
>>   * io.c (io_fwrite): preserve errno.  [ruby-core:27425]
>> 
>> 
>>   git-svn-id: http://svn.ruby-lang.org/repos/ruby/branches/ruby_1_8@26253
>> 
>> (snipped)
>> 
>> diff --git a/io.c b/io.c
>> index 375cbc8..d4d28e5 100644
>> --- a/io.c
>> +++ b/io.c
>> @@ -122,6 +122,9 @@ extern void Init_File _((void));
>> # endif
>> #endif
>> 
>> +#define preserving_errno(stmts) \
>> +	do {int saved_errno = errno; stmts; errno = saved_errno;} while (0)
>> +
>> VALUE rb_cIO;
>> VALUE rb_eEOFError;
>> VALUE rb_eIOError;
>> @@ -490,7 +493,7 @@ io_fwrite(str, fptr)
>> 	r = write(fileno(f), RSTRING(str)->ptr+offset, l);
>>        TRAP_END;
>> #if BSD_STDIO
>> -	fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET);
>> +	preserving_errno(fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET));
>> #endif
>>        if (r == n) return len;
>>        if (0 <= r) {
>> ---
>> Of course, the original reason for this fseeko() was to fix another
>> problem Unicorn exposed when mixing stdio + unistd calls...
>> 
>>  http://redmine.ruby-lang.org/issues/show/2267
>> 
>> -- 
>> Eric Wong
>> _______________________________________________
>> Unicorn mailing list - mongrel-unicorn@rubyforge.org
>> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
>> Do not quote signatures (like this one) or top post when replying
>> 
> 
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

To counter check I just built the latest ruby from source as well and the issue reappeared - so it happened between 26253 and tag/248

Kind regards, John

On 04.02.2010, at 15:22, John-Paul Bader wrote:

> Hey,
> 
> i checked out the revision 26253 built it and ran it and it seems to work again but: I didn't build it via FreeBSD ports so there might be a difference in configure / build options and I checked out the revision which included the change you suspect for causing the issue so I'm not sure if thats really helping us. Curling directly unicorn works without truncation and issues though.
> 
> Kind regards, John
> 
> On 04.02.2010, at 13:26, John-Paul Bader wrote:
> 
>> Hey again,
>> 
>> I will try to compile build the svn revision and let you know. I have to do some other work before that so I will report back in the evening (CEST / BERLIN) 
>> 
>> Thank you for helping out, kind regards,
>> 
>> John
>> 
>> On 04.02.2010, at 11:11, Eric Wong wrote:
>> 
>>> John-Paul Bader <hukl@h3q.com> wrote:
>>>> One more,
>>> 
>>> Hi,
>>> 
>>> About the exceptions, looks like you had '-d' (debug) instead of '-D'
>>> (daemonize) so it spewed every exception (even if trapped) to stderr.
>>> EAGAIN is common when dealing with non-blocking sockets.  Most of that
>>> is noise...
>>> 
>>> However the EINVAL in unicorn/http_response.rb is suspect.
>>> 
>>>> I reproduced the upgrading on my staging server which was still at the
>>>> old state in terms of software. I started by upgrading ruby from
>>>> 
>>>> ruby+nopthreads-1.8.7.160_5,1       -> ruby+nopthreads-1.8.7.248,1
>>>> ruby18-iconv-1.8.7.160,1                   -> ruby18-iconv-1.8.7.248,1
>>>> 
>>>> And voilá - the very same problems. So now I'm like what?
>>>> 
>>>> Is this rather a ruby than a unicorn issue ? Couldn't find any clues
>>>> in the changelog so far:
>>>> http://svn.ruby-lang.org/cgi-bin/viewvc.cgi/tags/v1_8_7_248/ChangeLog
>>> 
>>> That should narrow it down, so I start reading diffs from
>>> v1_8_7_160..v1_8_7_248 ...
>>> 
>>> Does backporting the following change in ruby_1_8
>>> (but not yet in the ruby_1_8_7 branch) fix things for you?
>>> 
>>> commit 841a57341ed43f5fa86489c12aceb25a232be820
>>> Author: nobu <nobu@b2dd03c8-39d4-4d8f-98ff-823fe69b080e>
>>> Date:   Fri Jan 8 09:51:23 2010 +0000
>>> 
>>>  * io.c (io_fwrite): preserve errno.  [ruby-core:27425]
>>> 
>>> 
>>>  git-svn-id: http://svn.ruby-lang.org/repos/ruby/branches/ruby_1_8@26253
>>> 
>>> (snipped)
>>> 
>>> diff --git a/io.c b/io.c
>>> index 375cbc8..d4d28e5 100644
>>> --- a/io.c
>>> +++ b/io.c
>>> @@ -122,6 +122,9 @@ extern void Init_File _((void));
>>> # endif
>>> #endif
>>> 
>>> +#define preserving_errno(stmts) \
>>> +	do {int saved_errno = errno; stmts; errno = saved_errno;} while (0)
>>> +
>>> VALUE rb_cIO;
>>> VALUE rb_eEOFError;
>>> VALUE rb_eIOError;
>>> @@ -490,7 +493,7 @@ io_fwrite(str, fptr)
>>> 	r = write(fileno(f), RSTRING(str)->ptr+offset, l);
>>>       TRAP_END;
>>> #if BSD_STDIO
>>> -	fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET);
>>> +	preserving_errno(fseeko(f, lseek(fileno(f), (off_t)0, SEEK_CUR), SEEK_SET));
>>> #endif
>>>       if (r == n) return len;
>>>       if (0 <= r) {
>>> ---
>>> Of course, the original reason for this fseeko() was to fix another
>>> problem Unicorn exposed when mixing stdio + unistd calls...
>>> 
>>> http://redmine.ruby-lang.org/issues/show/2267
>>> 
>>> -- 
>>> Eric Wong
>>> _______________________________________________
>>> Unicorn mailing list - mongrel-unicorn@rubyforge.org
>>> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
>>> Do not quote signatures (like this one) or top post when replying
>>> 
>> 
>> _______________________________________________
>> Unicorn mailing list - mongrel-unicorn@rubyforge.org
>> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
>> Do not quote signatures (like this one) or top post when replying
>> 
> 
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@h3q.com> wrote:
> To counter check I just built the latest ruby from source as well and
> the issue reappeared - so it happened between 26253 and tag/248

Keep in mind that 1.8.7-p248 is from the "ruby_1_8_7" branch, not the
"ruby_1_8" branch which contains r26253.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Hmm I see, kind of ;) 

Do you have a clue what is going wrong or any other things I could check out ?

Kind regards, John

On 04.02.2010, at 20:42, Eric Wong wrote:

> John-Paul Bader <hukl@h3q.com> wrote:
>> To counter check I just built the latest ruby from source as well and
>> the issue reappeared - so it happened between 26253 and tag/248
> 
> Keep in mind that 1.8.7-p248 is from the "ruby_1_8_7" branch, not the
> "ruby_1_8" branch which contains r26253.
> 
> -- 
> Eric Wong
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@berlin.ccc.de> wrote:
> Hmm I see, kind of ;) 
> 
> Do you have a clue what is going wrong or any other things I could
> check out ?

Can you just backport the r26253 change into your 1.8.7-p248
installation?  (see the patch in the previous email).  I'm fairly
certain that's it based on the EINVAL.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

I can of course, however I'd rather have an off the shelf ruby version out of the ports tree. 

But if there is currently no other way to fix this issue I will of course. I wonder if this issue always appears on ruby1.9. I will check that out too.

Kind regards, John

On 04.02.2010, at 21:14, Eric Wong wrote:

> John-Paul Bader <hukl@berlin.ccc.de> wrote:
>> Hmm I see, kind of ;) 
>> 
>> Do you have a clue what is going wrong or any other things I could
>> check out ?
> 
> Can you just backport the r26253 change into your 1.8.7-p248
> installation?  (see the patch in the previous email).  I'm fairly
> certain that's it based on the EINVAL.
> 
> -- 
> Eric Wong
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Hmm,

my C skills are really weak but this patch suppresses any IO errors right? At least on BSD? Can you explain what exactly it is doing? Just want to understand entirely.

I thought your diff was the ruby diff of r26253 and didn't realize it was yours ;)

Kind regards, John

On 04.02.2010, at 21:14, Eric Wong wrote:

> John-Paul Bader <hukl@berlin.ccc.de> wrote:
>> Hmm I see, kind of ;) 
>> 
>> Do you have a clue what is going wrong or any other things I could
>> check out ?
> 
> Can you just backport the r26253 change into your 1.8.7-p248
> installation?  (see the patch in the previous email).  I'm fairly
> certain that's it based on the EINVAL.
> 
> -- 
> Eric Wong
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

Sorry one more:

Is this something you will address sooner or later or is this a "ruby on bsd" bug?

Kind regards, John
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

One more ;)

Backporting on p248 fixed it.

Thanks, John

On 04.02.2010, at 21:48, John-Paul Bader wrote:

> Sorry one more:
> 
> Is this something you will address sooner or later or is this a "ruby on bsd" bug?
> 
> Kind regards, John
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@h3q.com> wrote:
> Sorry one more:
> 
> Is this something you will address sooner or later or is this a "ruby
> on bsd" bug?

This bug actually affects anything that writes to sockets/pipes on BSD,
not just Unicorn.  So the patch should be backported to 1.8.7 upstream.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@h3q.com> wrote:
> But if there is currently no other way to fix this issue I will of
> course. I wonder if this issue always appears on ruby1.9. I will check
> that out too.

The original problem doesn't affect 1.9 at all, 1.9 doesn't mix stdio
userspace wrapers with low-level unistd system calls.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[Eric Wong]

John-Paul Bader <hukl@h3q.com> wrote:
> Hmm,
> 
> my C skills are really weak but this patch suppresses any IO errors
> right? At least on BSD? Can you explain what exactly it is doing? Just
> want to understand entirely.

>From the beginning (a bit long, feel free to ask me for more
clarification, too much of this is second nature to me by now
and I may glance over important details...):

There are two standard ways of doing IO in C: stdio.h (fwrite(3)/
fread(3)/fseek(2) ...) and the lower-level Unix system calls found in
unistd.h (write(2)/read(2)/lseek(2)...)

stdio.h functions are wrappers that do buffering in userspace and wrap
the underlying unistd.h syscalls.  They should not be used
interchangeably on the same file descriptors.

Unfortunately, Ruby 1.8 makes this mistake and uses them interchangeably
in some places: bad.

So when working with regular files, file offsets maintained in userspace
via stdio did not get properly synchronized to the underlying
kernel-level file offsets.  That's why the fseeko(lseek()) was added to
fix an issue exposed by Unicorn.  lseek() was used to read the offset
from the kernel, and then fseeko() is then used to synchronize the
userspace offset to that of the kernel.   All of this works well for
seekable regular files.

Now, sockets and pipes aren't seekable, so you'll get an error from the
kernel if you try to seek on them.  Errors from system calls are stored
in "errno", a global variable that stores the error of the last system
call executed.  So since attempting to seek on an unseekable file sets
errno, it clobbers the previous clean (or the "safe" value of EAGAIN[1])
errno.

Eventually, this caused rb_sys_fail() function to be called, which
raises a Ruby exception matching the current value of errno.

[1] - EAGAIN (and EWOULDBLOCK on some systems) basically means "try
calling this same function again, later".  It gets returned when kernel
buffers (not the userspace ones) are full if attempting to write, or
empty if attempting to read.  Since Ruby 1.8 relies on non-blocking I/O
for sockets/pipes, the "blocking" write methods are coded to
(eventually) retry on EAGAIN.

> I thought your diff was the ruby diff of r26253 and didn't realize it
> was yours ;)

Actually, it's not mine, I just submitted the ticket that fixed one bug
and introduced the one you hit :)

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: "upstream timed out" after upgrades

[John-Paul Bader]

True, and there are already a couple issues filed concerning this.

Kind regards, John

On 04.02.2010, at 22:25, Eric Wong wrote:

> John-Paul Bader <hukl@h3q.com> wrote:
>> Sorry one more:
>> 
>> Is this something you will address sooner or later or is this a "ruby
>> on bsd" bug?
> 
> This bug actually affects anything that writes to sockets/pipes on BSD,
> not just Unicorn.  So the patch should be backported to 1.8.7 upstream.
> 
> -- 
> Eric Wong
> _______________________________________________
> Unicorn mailing list - mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
> Do not quote signatures (like this one) or top post when replying
> 

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying