Support

fantasydreaming · #1 12-08-2006, 09:09 AM

I'm getting tons of these, and I can't figure out why. Several per second when it's happening, which isn't always.

2006-12-07 20:19:27.370 [NOTICE] [136.182.158.153:61844-0#ap] Premature end of response header.
2006-12-07 20:19:27.709 [NOTICE] [24.171.94.109:2024-0#ap] Premature end of response header.
2006-12-07 20:19:27.822 [NOTICE] [69.246.14.128:2349-0#ap] Premature end of response header.

Also, when my rails application attempts to send a 404 header, litespeed sends a 503 header and doesn't log anything about why to it's stderr or error logfiles.

The logfile shows that a 200 response was sent - wierd!
67.171.73.40 - - [08/Dec/2006:11:07:26 -0600] "GET /asdfasdf2 HTTP/1.1" 200 - "-" "Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US; rv:1.8.0.4) Gecko/20060613 Camino/1.0.2"

Curl shows the 503 header
everybean:~/ap inspire$ curl --head http://allpoetry.com/asdfasdf2
HTTP/1.1 503 Service Unavailable
Server: LiteSpeed
Date: Fri, 08 Dec 2006 17:08:06 GMT
Connection: close

Lightppd at the localhost (sorry, rails' default), shows the proper header
everybean:~/ap inspire$ curl --head http://localhost:3000/asdfasdf2
HTTP/1.1 404 Not Found
Connection: close
Date: Fri, 08 Dec 2006 17:07:36 GMT
Content-Type: text/html; charset=iso-8859-1
Set-Cookie: _session_id=blah; path=/; expires=Fri, 05 Jan 2007 16:29:51 GMT
Cache-Control: no-cache
Expires: -1
Server: lighttpd/1.3.13

No core files, running 2.2.5 std, though the same happens on my other server running 2.2.6

Thanks for any help!

fantasydreaming · #2 12-08-2006, 09:10 AM

While testing the 404 -> 503 problems, no "premature response" messages were generated in the log, so likely they're different problems, but you never know.

mistwang · #3 12-08-2006, 09:49 AM

Premature end of response header probably is caused by crashed ruby process, which did not send back the response header or just half of it.
For 404 -> 503 problem, I don't know why it happens, maybe something wrong with that the way a routing error was handled in your application. Create a test Rails application and give it try.

fantasydreaming · #4 12-08-2006, 02:24 PM

1) Shouldn't crashed ruby processes show up in the error log?

2) The 404 is returned fine under lighttpd and webrick... it's only when litespeed is in the steps that it's a problem.

Exact same application, webrick @ port 3000, litespeed at port 80
everybean:~/storywrite inspire$ curl --head http://allpoetry.com:3000/testas3
HTTP/1.1 404 Not Found
Cache-Control: no-cache
Connection: Keep-Alive
Expires: -1
Date: Fri, 08 Dec 2006 22:24:25 GMT
Content-Type: text/html; charset=iso-8859-1
Server: WEBrick/1.3.1 (Ruby/1.8.5/2006-08-25)
Content-Length: 0
Set-Cookie: _session_id=bb2ed7dcf338e4dd1ccb730eb570b012; path=/; expires=Fri, 05 Jan 2007 22:24:05 GMT

everybean:~/storywrite inspire$ curl --head http://allpoetry.com/testas3
HTTP/1.1 503 Service Unavailable
Server: LiteSpeed
Date: Fri, 08 Dec 2006 22:24:34 GMT
Accept-Ranges: bytes
Connection: close
ETag: "dad-45799445-4ed154"
Last-Modified: Fri, 08 Dec 2006 16:35:17 GMT
Content-Type: text/html
Content-Length: 3501

mistwang · #5 12-08-2006, 02:44 PM

We need more information to figure out what exactly causing the problem.

Please try turn on LSWS debug logging by changing debug level to "high", post the section of error.log for the failed request.

Strace the ruby process. First send a good request to let the ruby process start, then do "strace -p <pid_of_ruby>", trace the process with larger PID. send a request result in 503 error, post the strace result.

check rails' log files.

mistwang · #6 12-08-2006, 02:55 PM

Are you using a 404 error page? Is it a static file or handled by rails as well. That could be the cause of 503 problem.

fantasydreaming · #7 12-09-2006, 07:19 AM

Short answer: The rails log shows it successfully processed. The strace of the Railsrunner shows it trying and closing the socket 3 times, and the web server agrees. I think perhaps it's something wrong with the LSAPI hating it when yous end a Status: header with the result?

LITESPEED LOG

2006-12-09 09:50:06.521 [DEBUG] [127.0.0.1:64798-0#storywrite] New request:
Method=[HEAD], URI=[/testas4],
QueryString=[]
Content Length=0
REWRITE] Rule: Match '/testas4' with pattern '^.*$', result: 1
REWRITE] stat( /Users/inspire/Projects/storywrite/public/../../down.html ) failed
REWRITE] Rule: Match '/testas4' with pattern '^$', result: -1
REWRITE] Rule: Match '/testas4' with pattern '^([^.]+)$', result: 2
REWRITE] Source URI: '/testas4' => Result URI: '/testas4.html'
REWRITE] Rule: Match '/testas4.html' with pattern '^(.*)$', result: 2
REWRITE] stat( /Users/inspire/Projects/storywrite/public/testas4.html ) failed
REWRITE] Source URI: '/testas4.html' => Result URI: 'dispatch.cgi'
REWRITE] Last Rule, stop!
Find context with URI: [/dispatch.cgi], location: []
processContextPath() return 0
run lsapi processor.
request [127.0.0.1:64798-0#storywrite:lsapi] is assigned with connection!
[ExtConn] reconnect()
[ExtConn] connecting to [uds://tmp/lshttpd/storywrite:_.sock]...
ExtConn::onWrite()
request header is done
ExtConn::continueRead()
Request body done!
ExtConn::suspendWrite()
processNewReq() return 0.
ExtConn::onRead()
LsapiConn::doRead()
process packet header 8 bytes
process packet header 0 bytes
ExtConn::onRead()
LsapiConn::doRead()
process packet header -1 bytes
connection to [uds://tmp/lshttpd/storywrite:_.sock] on request #0, error: Connection reset by peer!
[ExtConn] close()
No Request has been processed successfully through this connection, the maximum connections allowed will be reduced!
HttpExtConnector::tryRecover()...
trying to recover from connection problem, attempt: #1!
request [127.0.0.1:64798-0#storywrite:lsapi] is assigned with connection!
[ExtConn] reconnect()
[ExtConn] connecting to [uds://tmp/lshttpd/storywrite:_.sock]...
ExtConn::onWrite()
request header is done
ExtConn::continueRead()
Request body done!
ExtConn::suspendWrite()
ExtConn::onRead()
LsapiConn::doRead()
process packet header 8 bytes
process packet header 0 bytes
ExtConn::onRead()
LsapiConn::doRead()
process packet header -1 bytes
connection to [uds://tmp/lshttpd/storywrite:_.sock] on request #0, error: Connection reset by peer!
[ExtConn] close()
No Request has been processed successfully through this connection, the maximum connections allowed will be reduced!
HttpExtConnector::tryRecover()...
trying to recover from connection problem, attempt: #2!
request [127.0.0.1:64798-0#storywrite:lsapi] is assigned with connection!
[ExtConn] reconnect()
[ExtConn] connecting to [uds://tmp/lshttpd/storywrite:_.sock]...
ExtConn::onWrite()
request header is done
ExtConn::continueRead()
Request body done!
ExtConn::suspendWrite()
ExtConn::onRead()
LsapiConn::doRead()
process packet header 8 bytes
process packet header 0 bytes
o such file or directory
o such file or directory
ExtConn::onRead()
LsapiConn::doRead()
process packet header -1 bytes
connection to [uds://tmp/lshttpd/storywrite:_.sock] on request #0, error: Connection reset by peer!
[ExtConn] close()
No Request has been processed successfully through this connection, the maximum connections allowed will be reduced!
HttpExtConnector::tryRecover()...
HttpIOLink::continueWrite()...
write resumed!
HttpIOLink::handleEvents() events=4!
HttpIOLink::suspendWrite()...
HttpConnection::sendHttpError(),code=503 Service Unavailable
HttpConnection::flush()!
Written to client: 111
HttpConnection::nextRequest()!
HttpExtConnector::cleanUp() ...
abort request...
release ExtProcessor!
Non-KeepAlive, CLOSING!
Shutting down out-bound socket ...
HttpIOLink::handleEvents() events=17!
Close socket ...

******* STRACE OF RAILSRUNNER

select(1, [0], NULL, NULL, {1, 0}) = 1 (in [0], left {0, 525000})
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG|WSTOPPED, NULL) = 8839
wait4(-1, 0x7fbfffd454, WNOHANG|WSTOPPED, NULL) = 0
rt_sigreturn(0xffffffffffffffff) = 1
nanosleep({0, 10000}, NULL) = 0
select(1, [0], NULL, NULL, {0, 0}) = 1 (in [0], left {0, 0})
accept(0, {sa_family=AF_FILE, path="??<"}, [18051271735726047234]) = 3
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGC HLD, child_tidptr=0x2a955619d0) = 9153
close(3) = 0
select(1, [0], NULL, NULL, {1, 0}) = 0 (Timeout)
kill(8492, SIG_0) = 0
select(1, [0], NULL, NULL, {1, 0}) = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG|WSTOPPED, NULL) = 9153
wait4(-1, 0x7fbfffd454, WNOHANG|WSTOPPED, NULL) = 0
rt_sigreturn(0xffffffffffffffff) = -1 EINTR (Interrupted system call)
select(1, [0], NULL, NULL, {0, 953000}) = 1 (in [0], left {0, 575000})
nanosleep({0, 10000}, 0) = ? ERESTART_RESTARTBLOCK (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG|WSTOPPED, NULL) = 8502
wait4(-1, 0x7fbfffd474, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (No child processes)
rt_sigreturn(0xffffffffffffffff) = -1 EINTR (Interrupted system call)
select(1, [0], NULL, NULL, {0, 0}) = 1 (in [0], left {0, 0})
accept(0, {sa_family=AF_FILE, path="??<"}, [18051271735726047234]) = 3
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGC HLD, child_tidptr=0x2a955619d0) = 9154
close(3) = 0
select(1, [0], NULL, NULL, {1, 0}) = 0 (Timeout)
kill(8492, SIG_0) = 0
select(1, [0], NULL, NULL, {1, 0}) = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG|WSTOPPED, NULL) = 9154
wait4(-1, 0x7fbfffd454, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (No child processes)
rt_sigreturn(0xffffffffffffffff) = -1 EINTR (Interrupted system call)
select(1, [0], NULL, NULL, {0, 934000}) = 0 (Timeout)

****** RAILS LOG ********

Processing UserController#show (for 67.171.73.40 at 2006-12-09 09:17:35) [HEAD]
Session ID: 0ca5e149498d890db933851b193e6421
Parameters: {"action"=>"show", "id"=>"testas6", "controller"=>"user"}
*application.rb:124 reloading vars, last was 2 hours ago
MemCache Get online
MemCache Get user/show/testas6
User Load (0.000910) SELECT * FROM users WHERE (name='testas6') LIMIT 1
Namechange Load (0.000369) SELECT * FROM ap.namechanges WHERE (start='testas6') ORDER BY created_at desc LIMIT 1
Rendering public/404.html (404)
MemCache Put session:0ca5e149498d890db933851b193e6421 expires 0
UserController: missing default helper path user_helper
MemCache Get session:bda40d81bf8501de7187f7beb6b71e3f

mistwang · #8 12-09-2006, 12:12 PM

The lsws log shows that, ruby just simply closed the connection, not sending anything back.

The ruby process you straced is the parent ruby process which does nothing but accept a connection and fork a child ruby process to handle the request. I really interested is what happened in the child process. I think it crashed, probably.

Is the rails log from litespeed or from other setup?

Are you setup your Rails app with the easy configuration? or step by step manually?
You are using rewrite rules to dispatch the request, have you tried using 404 handler?

Let me know your exact rails setup, I will try to duplicate it in our lab.

fantasydreaming · #9 12-09-2006, 12:29 PM

I'm using the "easy" setup. I could try switching to the manual one... So it's 404 handler is automatically handling the ruby process? Maybe it's angry that I'm returning 404 again, so it tries to send it back to the 404 handler, which sends it there again ... etc.

Rails "suexec virtual host" template included, I turned off "restricted, changed the user/group to a new user, and added the rewrite rules:
RewriteRule ^$ index.html [QSA]
RewriteRule ^([^.]+)$ $1.html [QSA]
RewriteCond %{REQUEST_FILENAME} !-f
RewriteRule ^(.*)$ dispatch.cgi [QSA,L]

How would I get the PID of the actual ruby process? Does it have the same name as "ruby /opt/lsws/fcgi-bin/RailsRunner.rb"? Each "process" really starts two of these? It thought it was the web server that handled the forking/etc...?