entries in error_log

anewday

Well-Known Member
#1
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. :)
 

anewday

Well-Known Member
#6
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. :)
 

anewday

Well-Known Member
#7
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:

mistwang

LiteSpeed Staff
#8
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".
 

anewday

Well-Known Member
#9
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.
 

anewday

Well-Known Member
#11
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.
 

mistwang

LiteSpeed Staff
#12
"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.
 

anewday

Well-Known Member
#13
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:

anewday

Well-Known Member
#14
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:

anewday

Well-Known Member
#16
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:

anewday

Well-Known Member
#18
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:

mistwang

LiteSpeed Staff
#19
It is a network problem.
2008-04-16 12:05:16.143 INFO [189.x.x.x.3:2001-1#APVH_forum......com] Request body size: 255071, received: 69696.
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.
 
Top