Client never gets server response

Discussion in 'Ruby/Rails' started by Renuplex, Apr 19, 2007.

  1. Renuplex

    Renuplex New Member

    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
  2. mistwang

    mistwang LiteSpeed Staff

  3. Renuplex

    Renuplex New Member

    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
  4. Renuplex

    Renuplex New Member

    Sorry, debug does work and I'm looking into it...
  5. Renuplex

    Renuplex New Member

    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() ...
  6. Renuplex

    Renuplex New Member

    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...
  7. mistwang

    mistwang LiteSpeed Staff

    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.
  8. Renuplex

    Renuplex New Member

    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
  9. mistwang

    mistwang LiteSpeed Staff

    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".
  10. Renuplex

    Renuplex New Member

    Hi and thanks mistwang!

    I finally got my Rails app working properly on Litespeed!

    Thanks alot for the good support!
    Laurent

Share This Page