Client never gets server response

R

Renuplex

Member
#1
#1
Hi,

I have setup a Rails app using AJAX and I am experiencing a strange behavior: I am using a form_remote_tag to post data and execute some fairly heavy calculation (about 10-30sec) on the server side. My browser only shows the action while executing the query but never gets the results back from the server.
However when looking at the logs I don't see any errors, be it on the LS or the ruby server. The ruby server actually logs a 200 response.

I suspect this is due to the long processing time and I've tried to set the timeouts in consequence on the LS server however I apparently didn't find the right parameter.

I'd also like to precise that the app runs fine on mongrel f.ex.

any hints?

Thanks alot,
Laurent
 
R

Renuplex

Member
#3
#3
Hi,

Thanks for your advice. I've set both of these timeouts to 600secs which should be plenty.

For some reason I can't see any entries in the access log and neither in the error log even with debug level to high.

What do you mean by 'Make sure to leave enough headroom. ' ?

Thanks,
Laurent
 
R

Renuplex

Member
#5
#5
So in the debug log, the only I get this:

2007-04-19 18:21:58.320 [DEBUG] [128.178.83.29:2105-7#railsapp] New request:
Method=[POST], URI=[/route/search],
QueryString=[]
Content Length=80
2007-04-19 18:21:58.320 [DEBUG] [128.178.83.29:2105-7#railsapp] Read Request Body!
2007-04-19 18:21:58.320 [DEBUG] [128.178.83.29:2105-7#railsapp] Read from client: 0
2007-04-19 18:21:58.320 [DEBUG] [128.178.83.29:2105-7#railsapp] processNewReq() return 0.
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] HttpIOLink::handleEvents() events=1!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] HttpConnection::eek:nReadEx(), state: 2!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Read Request Body!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Read from client: 80
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Finsh request body 80/80 bytes!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Finished request body 80 bytes!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Find context with URI: [/], location: [/home/rrg/trunk/Rails/frontend/Prototype/public/]
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] File not found [/home/rrg/trunk/Rails/frontend/Prototype/public/route/search]
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] processContextPath() return 25
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] HttpConnection::sendHttpError(),code=404 Not Found^M
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] redirect to:
URI=[/dispatch.lsapi],
QueryString=[]
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] Find context with URI: [/dispatch.lsapi], location: []
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] processContextPath() return 0
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp] run lsapi processor.
2007-04-19 18:21:58.321 [DEBUG] [uds://tmp/lshttpd/railsapp:_.sock] connection available!
2007-04-19 18:21:58.321 [DEBUG] [uds://tmp/lshttpd/railsapp:_.sock] request [128.178.83.29:2105-7#railsapp:lsapi] is assigned with connection!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] request header is done
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::continueRead()
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] processor sent request body 80 bytes, total sent: 80
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Request body done!
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::suspendWrite()
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::eek:nRead()
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] LsapiConn::doRead()
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:21:58.321 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 0 bytes
2007-04-19 18:21:59.116 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::eek:nRead()
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] LsapiConn::doRead()
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process response header 8 bytes
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process response stream 8227 bytes, packet left: 8227
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 0 bytes
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] use CHUNKED encoding!
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] call pConn->writeRespBody() to write 107 bytes
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Written to client: 1664
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] pConn->writeRespBody() return 107
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] response buffer is empty, suspend HttpConn write!
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpIOLink::suspendWrite()...
2007-04-19 18:22:02.118 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] m_pHandler->onWrite() return 1
2007-04-19 18:22:04.116 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::eek:nRead()
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] LsapiConn::doRead()
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process response stream 8233 bytes, packet left: 8233
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] response header finished!
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] GZIP response body!
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 0 bytes
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] call pConn->writeRespBody() to write 967 bytes
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Written to client: 974
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] pConn->writeRespBody() return 967
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] response buffer is empty, suspend HttpConn write!
2007-04-19 18:22:04.268 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpIOLink::suspendWrite()...
2007-04-19 18:22:05.490 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::eek:nRead()
2007-04-19 18:22:05.490 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] LsapiConn::doRead()
2007-04-19 18:22:05.490 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:22:05.490 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process response stream 13398 bytes, packet left: 13398
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 0 bytes
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] call pConn->writeRespBody() to write 1665 bytes
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Written to client: 1672
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] pConn->writeRespBody() return 1665
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] response buffer is empty, suspend HttpConn write!
2007-04-19 18:22:05.491 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpIOLink::suspendWrite()...
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ExtConn::eek:nRead()
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] LsapiConn::doRead()
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] process packet header 8 bytes
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] [EXT] EndResponse( endCode=0, protocolStatus=0 )
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] release ExtProcessor!
2007-04-19 18:22:05.505 [DEBUG] [uds://tmp/lshttpd/railsapp:_.sock] add recycled connection to connection pool!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpIOLink::continueWrite()...
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] write resumed!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpIOLink::handleEvents() events=4!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] call pConn->writeRespBody() to write 10 bytes
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Written to client: 15
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] pConn->writeRespBody() return 10
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] ReqBody: 80, RespBody: 2749, HEC_COMPLETE!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] m_pHandler->onWrite() return 0
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] Written to client: 5
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpConnection::flush()!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpConnection::nextRequest()!
2007-04-19 18:22:05.505 [DEBUG] [128.178.83.29:2105-7#railsapp:lsapi] HttpExtConnector::cleanUp() ...
 
R

Renuplex

Member
#6
#6
2007-04-19 18:22:09.108 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:14.107 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:19.108 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:24.108 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:29.108 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:34.111 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:39.105 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:44.109 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:49.104 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:54.104 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:22:57.016 [DEBUG] [128.178.83.29:2102-7] Keep-alive timeout, close!
2007-04-19 18:22:57.016 [DEBUG] [128.178.83.29:2102-7] Close socket ...

2007-04-19 18:22:59.105 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:23:04.105 [DEBUG] Failed to execute 'mpstat' command: No such file or directory
2007-04-19 18:23:05.716 [DEBUG] [128.178.83.29:2105-8] Keep-alive timeout, close!
2007-04-19 18:23:05.716 [DEBUG] [128.178.83.29:2105-8] Close socket ...

I'm sorry for this massive post, but I've lots of trouble seeing what is exactly happening. I'm quite novice with both Rails and Litespeed...
 
M

mistwang

LiteSpeed Staff
#7
#7
This is caused by a bug when the reply is very big, we had fixed this problem in 3.0.3, please give it a try. However, the maximum reply header size limit might be hit.
The limit in LSWS is 8K.
 
R

Renuplex

Member
#8
#8
Thanks for your hint mistwang!

I installed version 3.0.3 and figured the source of the problem:

I'm using some 'puts' statements to log some of the things in my code and they are directly redirected and taken as header thus creating monstruous headers for the response sometimes.
Whilst I know it is probably rather bad practice to use 'puts' to log/debug my app, I have 2 questions:

1. Is there a way to change this in Litespeed (i.e. only considering the actual response as mongrel does)
2. If I use some logger class in ruby, will it work? (What if some libs do not log properly tho?)

Thanks,
Laurent
 
M

mistwang

LiteSpeed Staff
#9
#9
LiteSpeed follow the standard CGI route, so STDOUT goes in response. So, it is not possible to make LiteSpeed act as mongrel at this moment, we will try something.

For logging purpose, please use "STDERR".
 
You must log in or register to reply here.
Top