entries in error_log

Discussion in 'General' started by anewday, Apr 14, 2008.

  1. anewday

    anewday Moderator

    Hi George, some members on my forum were complaining of time out errors, a refresh would fix it. I checked the error_log for his IP and saw these out of many.

    Code:
    2008-03-31 10:14:21.704 [INFO] [147.x.x.x197:56558-0#APVH_myforum] Connection idle time: 31 while in state: 5 watch
    ing for event: 25,close!
    2008-03-31 10:14:21.704 [NOTICE] [147.x.x.x197:56558-0#APVH_myforum] Content len: 0, Request line: 
    2008-03-31 10:14:21.704 [NOTICE] [147.x.x.x197:56558-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-03-31 10:14:21.704 [INFO] [147.x.x.x197:56558-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-03-31 15:26:11.613 [INFO] [147.x.x.x197:60890-0] Connection idle time: 31 while in state: 1 watching for event: 25,close!
    2008-03-31 15:26:11.613 [NOTICE] [147.x.x.x197:60890-0] Content len: 0, Request line: 
    2008-04-08 11:55:56.558 [INFO] [147.x.x.x197:56793-0#APVH_myforum] Connection idle time: 32 while in state: 5 watch
    ing for event: 25,close!
    2008-04-08 11:55:56.558 [NOTICE] [147.x.x.x197:56793-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-08 11:55:56.558 [INFO] [147.x.x.x197:56793-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-04-08 12:39:26.818 [INFO] [147.x.x.x197:57389-0#APVH_myforum] Connection idle time: 31 while in state: 5 watch
    ing for event: 25,close!
    2008-04-08 12:39:26.818 [NOTICE] [147.x.x.x197:57389-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-08 12:39:26.818 [NOTICE] [147.x.x.x197:57389-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-04-08 12:39:26.818 [INFO] [147.x.x.x197:57389-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-04-08 12:40:38.834 [INFO] [147.x.x.x197:57395-0#APVH_myforum] Connection idle time: 33 while in state: 5 watch
    ing for event: 25,close!
    2008-04-08 12:40:38.834 [NOTICE] [147.x.x.x197:57395-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-08 12:40:38.834 [NOTICE] [147.x.x.x197:57395-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-04-08 12:40:38.834 [INFO] [147.x.x.x197:57395-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-04-08 13:40:06.304 [INFO] [147.x.x.x197:58695-0#APVH_myforum] Connection idle time: 31 while in state: 5 watch
    ing for event: 25,close!
    2008-04-08 13:40:06.304 [NOTICE] [147.x.x.x197:58695-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-08 13:40:06.304 [INFO] [147.x.x.x197:58695-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-04-08 14:11:29.235 [INFO] [147.x.x.x197:59502-0#APVH_myforum] Connection idle time: 31 while in state: 5 watch
    ing for event: 25,close!
    2008-04-08 14:11:29.235 [NOTICE] [147.x.x.x197:59502-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-08 14:11:29.235 [NOTICE] [147.x.x.x197:59502-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-04-08 14:11:29.235 [INFO] [147.x.x.x197:59502-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-04-11 12:25:54.911 [INFO] [147.x.x.x197:52782-0#APVH_myforum] Connection idle time: 31 while in state: 5 watch
    ing for event: 25,close!
    2008-04-11 12:25:54.911 [NOTICE] [147.x.x.x197:52782-0#APVH_myforum] Content len: 0, Request line: 
    2008-04-11 12:25:54.911 [NOTICE] [147.x.x.x197:52782-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-04-11 12:25:54.911 [INFO] [147.x.x.x197:52782-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0,
     response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    2008-03-25 01:01:47.127 [INFO] [59.x.x.x:1679-0#APVH_myforum] Connection idle time: 16 while in state: 5 watching
     for event: 25,close!
    2008-03-25 01:01:47.127 [NOTICE] [59.x.x.x:1679-0#APVH_myforum] Content len: 0, Request line: 
    2008-03-25 01:01:47.127 [NOTICE] [59.x.x.x:1679-0#APVH_myforum] Redirect: #1, URL: /index.php
    2008-03-25 01:01:47.127 [INFO] [59.x.x.x:1679-0#APVH_myforum] HttpExtConnector state: 8, request body sent: 0, response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.
    
    And I also noticed many of the following in the log, not sure if it's related to the issue above or not.

    Code:
    2008-03-23 16:39:53.638 [INFO] [74.6.25.173:51069-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on r
    equest #1, error: Connection reset by peer!
    2008-04-01 06:08:27.901 [INFO] [151.56.134.192:17138-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] o
    n request #2, error: Connection reset by peer!
    2008-04-01 07:24:50.521 [INFO] [67.x.x.x:46159-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #25, error: Connection reset by peer!
    2008-04-01 07:24:50.617 [INFO] [67.x.x.x:46159-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:24:50.714 [INFO] [67.x.x.x:46159-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #81, error: Connection reset by peer!
    2008-04-01 07:25:02.138 [INFO] [67.x.x.x:54397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #51, error: Connection reset by peer!
    2008-04-01 07:25:02.364 [INFO] [67.x.x.x:54397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:25:02.590 [INFO] [67.x.x.x:54397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #2, error: Connection reset by peer!
    2008-04-01 07:25:11.490 [INFO] [67.x.x.x:43047-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #40, error: Connection reset by peer!
    2008-04-01 07:25:11.596 [INFO] [67.x.x.x:43047-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:25:11.740 [INFO] [67.x.x.x:43047-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #13, error: Connection reset by peer!
    2008-04-01 07:25:30.348 [INFO] [67.x.x.x:46340-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #20, error: Connection reset by peer!
    2008-04-01 07:25:30.449 [INFO] [67.x.x.x:46340-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:25:30.545 [INFO] [67.x.x.x:46340-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #67, error: Connection reset by peer!
    2008-04-01 07:26:08.347 [INFO] [67.x.x.x:58025-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #17, error: Connection reset by peer!
    2008-04-01 07:26:08.444 [INFO] [67.x.x.x:58025-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:26:08.555 [INFO] [67.x.x.x:58025-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #1, error: Connection reset by peer!
    2008-04-01 07:27:02.059 [INFO] [67.x.x.x:59397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #30, error: Connection reset by peer!
    2008-04-01 07:27:02.162 [INFO] [67.x.x.x:59397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:27:02.263 [INFO] [67.x.x.x:59397-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #7, error: Connection reset by peer!
    2008-04-01 07:28:09.624 [INFO] [67.x.x.x:58235-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #35, error: Connection reset by peer!
    2008-04-01 07:28:09.784 [INFO] [67.x.x.x:58235-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:28:10.004 [INFO] [67.x.x.x:58235-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #40, error: Connection reset by peer!
    2008-04-01 07:28:41.033 [INFO] [67.x.x.x:49674-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #26, error: Connection reset by peer!
    2008-04-01 07:28:41.251 [INFO] [67.x.x.x:49674-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #0, error: Connection reset by peer!
    2008-04-01 07:28:41.450 [INFO] [67.x.x.x:49674-0#APVH_myforum] connection to [uds://tmp/lshttpd/lsphp4.sock] on 
    request #9, error: Connection reset by peer!
    
    Could you tell me what those errors mean and how to fix it? Thank you. :)
  2. mistwang

    mistwang LiteSpeed Staff

    Please update to the latest 3.3.10 release package uploaded today, there might be a problem with request rate throttling.
  3. anewday

    anewday Moderator

    Thanks, is it also applied to 4.0 beta 1? I plan to try that later today or tomorrow.
  4. mistwang

    mistwang LiteSpeed Staff

    Yeah, 4.0 beta 1 package has been updated as well.
  5. mistwang

    mistwang LiteSpeed Staff

    seems 4.0b1 still has a bug with request rate throttling, do not use it in production yet.
  6. anewday

    anewday Moderator

    Ok, I was just about to download it. I think I'll upgrade to 3.3.10 first and wait for beta 2 to test the 4.0. Thanks for the heads up. :)
  7. anewday

    anewday Moderator

    Hi, I sent you a PM with more entries from error_log.

    Please take a look, how can I prevent 503 service unavailable errors? I've never met this error with Apache during high loads. Thank you.
    Last edited: Apr 15, 2008
  8. mistwang

    mistwang LiteSpeed Staff

    You can try set PHP_LSAPI_CHILDREN a little higher than "Max Conn", sometimes, a PHP children process could be not responding due to canceled requests or something. like "max conn = 40", "PHP_LSAPI_CHILDREN=50".
  9. anewday

    anewday Moderator

    Ok, is it also good to increase the Memory soft and hard limits? It's set to 250M and 300M respectively. Process soft and hard limit is set to 100M and 150M.

    I thought those are related to the 503 service unavailable errors. It's weird that with Apache, it would at least load the pages, albeit slow, won't display a 503 error.
  10. mistwang

    mistwang LiteSpeed Staff

    Get rid of the trialling 'M', 250/300 should be enough for your setup.
  11. anewday

    anewday Moderator

    Ok, there wasn't the trailing M on the web console. It's strange that during the time the load was very high and many saw those 503 unavailable errors...there was over 2GB of free cached memory according to the graphs.

    Thanks for your help.
  12. mistwang

    mistwang LiteSpeed Staff

    "Process soft limit" could be the cause. You need to count the number of processes running as "nobody" during peak time. if it anywhere close to the limit, you should increase the limit.
  13. anewday

    anewday Moderator

    Ok, an active user on the forums just reported seeing a 408 error and the load was under 2. :confused:

    2008-04-15 16:18:46.001 INFO [147.x.x.x:51735-0#APVH_forum.....com] Connection idle time: 31 while in state: 5 watching for event: 25,close!
    2008-04-15 16:18:46.001 NOTICE [147.x.x.x:51735-0#APVH_forum.....com] Content len: 198, Request line:
    POST /index.php? HTTP/1.1
    2008-04-15 16:18:46.001 INFO [147.x.x.x:51735-0#APVH_forum....com] HttpExtConnector state: 8, request body sent: 198, response body size: 0, response body sent:0, left in buffer: 0, attempts: 0.

    Maybe there is still a bug with the rate throttling? I will increase the process soft and hard limits.
    Last edited: Apr 15, 2008
  14. anewday

    anewday Moderator

    George, are these normal in the log? It appears often.

    Code:
    2008-04-15 17:13:09.039	INFO	[AdminPHP] pid list size: 0, pid stop list size: 0
    2008-04-15 17:13:09.039	NOTICE	[AdminPHP] stop worker processes
    2008-04-15 17:17:17.457	INFO	[AdminPHP] pid list size: 1
    2008-04-15 17:17:17.457	INFO	[AdminPHP] add child process pid: 2726
    2008-04-15 17:30:09.520	INFO	Remove pid: 2726
    2008-04-15 17:30:09.520	INFO	Pid: 2726 associated with [AdminPHP]
    2008-04-15 17:30:09.520	INFO	[AdminPHP] pid list size: 0, pid stop list size: 0
    2008-04-15 17:30:09.520	NOTICE	[AdminPHP] stop worker processes
    2008-04-15 17:40:43.933	INFO	[AdminPHP] pid list size: 1
    2008-04-15 17:40:43.933	INFO	[AdminPHP] add child process pid: 5299
    Last edited: Apr 15, 2008
  15. mistwang

    mistwang LiteSpeed Staff

    It is normal.
  16. anewday

    anewday Moderator

    I still see occassional entries in the error_log when the load is under 1

    Code:
    2008-04-16 12:05:16.143	INFO	[189.x.x.x:2001-1#APVH_forum........com] Connection idle time: 31 while in state: 2 watching for event: 25,close!
    2008-04-16 12:05:16.143	NOTICE	[189.x.x.x:2001-1#APVH_forum.......com] Content len: 255071, Request line:
    POST /index.php?auth_key=bc6b6630ba1629d2541aff9f7bc59070 HTTP/1.1
    2008-04-16 12:05:16.143	INFO	[189.x.x.x.3:2001-1#APVH_forum......com] Request body size: 255071, received: 69696.
    That active user writes often on the forums.

    Static Req/s 50
    Dynamic Req/s 10
    Soft Limit 40
    Hard Limit 70
    Grace 60

    Usually, those errors appear often when the server is busy.
    Last edited: Apr 16, 2008
  17. mistwang

    mistwang LiteSpeed Staff

    That's normal, more likely caused by network problem when browser send the request. Like a modem drops the connection or something.
  18. anewday

    anewday Moderator

    I don't think so, whenever the load is high, it always show those in the log. I noticed that the lines contain POST almost every time, seems like a member is trying to post to the forums. Why can't it just process them anyway (although slower) instead of giving those 408 timeout errors. Errors on the screen is not good for visitors to see. I rather have it run slower than having an error displayed. :(

    I think I'm going to switch back to Apache soon, at least it doesn't show 503, 408 errors...still processes every request, just slower during high load periods. It's a shame I have to do this, lsws is a wonderful product but it has some flaws not present in Apache...
    Last edited: Apr 20, 2008
  19. mistwang

    mistwang LiteSpeed Staff

    It is a network problem.
    shows that the request body has not been completely received yet.
    Are you using bandwidth throttling?

    You can try increasing the "Connection timeout" under "Server"->tuning tab.
  20. anewday

    anewday Moderator

    I'm not using any bandwidth throttling of any kind. Connection timeout is set to 30.

Share This Page