Random 404 pages

Discussion in 'Bug Reports' started by gwhite, Oct 21, 2008.

  1. gwhite

    gwhite New Member

    We are seeing in our access logs random 404 errors with one of our Rails Apps. We can't pinpoint a cause at this stage - seemingly users who are experiencing it can refresh the page and everything will be fine.
    One thing we did notice was the "[NOTICE]..Request line:" message which is typically followed by the request is empty for these 404 errors.
    We have evidence that rails itself is completing these requests despite the 404.
    This is on a CentOS 5 platform with standard Litespeed version 3.3.18. I have attached a debug log that shows the access-log entries with 404s and the debug logging output.

    192.168.100.1 - - [17/Oct/2008:13:45:02 -0700] "GET /website HTTP/1.1" 404 - "http://referer.com" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; WOW64; SLCC1; .NET CLR 2.0.50727; .NET CLR 3.0.04506; Media Center PC 5.0)"

    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31] HttpConnection::eek:nReadEx(), state: 0!
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31] readToHeaderBuf().
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31] read 959 bytes to header buffer
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31] processHeader() return 0, header state: 3.
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31] readToHeaderBuf() return 0.
    2008-10-17 13:45:02.201 [NOTICE] [192.168.100.1:50252-31#thewebapp] Content len: 0, Request line:
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] File not found [/path/to/thewebapp/releases/20081015231404/public/website]
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] processContextPath() return 25
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] processNewReq() return 25.
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] HttpConnection::sendHttpError(),code=404 Not Found
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] redirect to:
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] processContextPath() return 0
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp] run lsapi processor.
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] ExtConn::continueRead()
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] ExtConn::suspendWrite()
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] ExtConn::eek:nRead()
    2008-10-17 13:45:02.201 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] LsapiConn::doRead()
    2008-10-17 13:45:03.381 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] HttpIOLink::suspendRead()...
    2008-10-17 13:45:03.381 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] [LSAPI] send abort packet!
    2008-10-17 13:45:03.381 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] Shutting down SSL ...
    2008-10-17 13:45:03.382 [DEBUG] [192.168.100.1:50252-31#thewebapp:lsapi] Close socket ...

    74.222.1.1 - - [17/Oct/2008:14:05:51 -0700] "GET /website/manager HTTP/1.1" 404 171 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.3) Gecko/2008092417 Firefox/3.0.3"

    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1] HttpConnection::eek:nReadEx(), state: 0!
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1] readToHeaderBuf().
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1] read 667 bytes to header buffer
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1] processHeader() return 0, header state: 3.
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1] readToHeaderBuf() return 0.
    2008-10-17 14:05:51.577 [NOTICE] [74.222.1.1:2486-1#thewebapp] Content len: 0, Request line:
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] File not found [/path/to/thewebapp/releases/20081015231404/public/website/manager]
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] processContextPath() return 25
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] processNewReq() return 25.
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] HttpConnection::sendHttpError(),code=404 Not Found
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] redirect to:
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] processContextPath() return 0
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp] run lsapi processor.
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] ExtConn::continueRead()
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] ExtConn::suspendWrite()
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] ExtConn::eek:nRead()
    2008-10-17 14:05:51.577 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] LsapiConn::doRead()
    2008-10-17 14:05:51.585 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] ExtConn::eek:nRead()
    2008-10-17 14:05:51.585 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] LsapiConn::doRead()
    2008-10-17 14:05:51.585 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] GZIP response body!
    2008-10-17 14:05:51.585 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] use CHUNKED encoding!
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] HttpIOLink::suspendWrite()...
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] ExtConn::eek:nRead()
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] LsapiConn::doRead()
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] [EXT] EndResponse( endCode=0, protocolStatus=0 )
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] HttpIOLink::continueWrite()...
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] write resumed!
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] HttpConnection::flush()!
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] HttpIOLink::flushSSL()...
    2008-10-17 14:05:51.586 [DEBUG] [74.222.1.1:2486-1#thewebapp:lsapi] HttpConnection::nextRequest()!
  2. mistwang

    mistwang LiteSpeed Staff

    For some reason, the first request was aborted.
    [LSAPI] send abort packet!

    Maybe something wrong with HTTP request from "Media Center PC 5.0" browser.

    The second request is successfully completed, just the status code has not been change from 404 to 200, the rails app does not set it. So, it is normal.

    Please try 3.3.20 see if it help or not.

Share This Page