entries in error_log

[anewday]

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.

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.

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.

 

[mistwang]

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

 

[anewday]

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

 

[mistwang]

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

 

[mistwang]

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

 

[anewday]

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]

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.

 

[mistwang]

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]

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.

 

[mistwang]

Process soft and hard limit is set to 100M and 150M

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

 

[anewday]

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]

"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]

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

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.

 

[anewday]

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

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

 

[mistwang]

It is normal.

 

[anewday]

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

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.

 

[mistwang]

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

 

[anewday]

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

 

[mistwang]

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.

 

[anewday]

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