You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Mark Thomas <ma...@apache.org> on 2011/02/21 16:21:32 UTC
Reaching ulimit values for open files can generate huge log files
The ASF Sonar installation managed to generate 46GB of identical log
messages [1] today in the 8 hours it took to notice it was down.
While better monitoring would/should have identified the problem sooner,
it does demonstrate a problem with the acceptor threads in all three
endpoints. If there is a system-level issue that causes the accept()
call to always fail (such as hitting the ulimit) then the endpoint
essentially enters a loop where it logs an error message for every
iteration of the loop. This will result in many log messages per second.
I'd like to do something about this. I was thinking of something along
the lines of the following for each endpoint.
Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
===================================================================
--- java/org/apache/tomcat/util/net/JIoEndpoint.java (revision 1072939)
+++ java/org/apache/tomcat/util/net/JIoEndpoint.java (working copy)
@@ -183,9 +183,19 @@
@Override
public void run() {
+ int errorDelay = 0;
+
// Loop until we receive a shutdown command
while (running) {
+ if (errorDelay > 0) {
+ try {
+ Thread.sleep(errorDelay);
+ } catch (InterruptedException e) {
+ // Ignore
+ }
+ }
+
// Loop if endpoint is paused
while (paused && running) {
try {
@@ -225,9 +235,15 @@
// Ignore
}
}
+ errorDelay = 0;
} catch (IOException x) {
if (running) {
log.error(sm.getString("endpoint.accept.fail"), x);
+ if (errorDelay == 0) {
+ errorDelay = 50;
+ } else if (errorDelay < 1600) {
+ errorDelay = errorDelay * 2;
+ }
}
} catch (NullPointerException npe) {
if (running) {
Thoughts / comments?
Mark
[1] http://pastebin.com/CrsujeW4
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Mark,
On 2/21/2011 10:21 AM, Mark Thomas wrote:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
Ugh. Yeah, that sucks.
Hitting the ulimit doesn't necessarily mean disaster and the process
could still recover. For instance, an out-of-control request might try
to open files in a loop and tie up all the fds for a minute or two
before the request dies and the GC cleans everything back up. In the
meantime, some request processors might suffer but eventually recover.
> While better monitoring would/should have identified the problem sooner,
> it does demonstrate a problem with the acceptor threads in all three
> endpoints. If there is a system-level issue that causes the accept()
> call to always fail (such as hitting the ulimit) then the endpoint
> essentially enters a loop where it logs an error message for every
> iteration of the loop. This will result in many log messages per second.
I like this idea. Does that mean that you'll get once-per-second (or
whatever) errors across all processor threads or once-per-second errors
for each processor thread?
> + if (errorDelay == 0) {
> + errorDelay = 50;
How about making this initial delay configurable?
> + } else if (errorDelay < 1600) {
How about making this maximum delay configurable?
> + errorDelay = errorDelay * 2;
Geometric growth seems reasonable... I don't see a reason to make this
multiplier configurable.
-chris
Re: Reaching ulimit values for open files can generate huge log files
Posted by Ian Darwin <ia...@darwinsys.com>.
On 02/21/11 10:21, Mark Thomas wrote:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
Continuing to drive down the cost of disk storage :-)
> While better monitoring would/should have identified the problem sooner,
> it does demonstrate a problem with the acceptor threads in all three
> endpoints. If there is a system-level issue that causes the accept()
> call to always fail (such as hitting the ulimit) then the endpoint
> essentially enters a loop where it logs an error message for every
> iteration of the loop. This will result in many log messages per second.
>
> I'd like to do something about this. I was thinking of something along
> the lines of the following for each endpoint.
>
> Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
> ===================================================================
> --- java/org/apache/tomcat/util/net/JIoEndpoint.java (revision 1072939)
> +++ java/org/apache/tomcat/util/net/JIoEndpoint.java (working copy)
> @@ -183,9 +183,19 @@
> @Override
> public void run() {
>
> + int errorDelay = 0;
> +
> // Loop until we receive a shutdown command
> while (running) {
>
> + if (errorDelay > 0) {
> + try {
> + Thread.sleep(errorDelay);
> + } catch (InterruptedException e) {
> + // Ignore
> + }
> + }
> +
> // Loop if endpoint is paused
> while (paused && running) {
> try {
> @@ -225,9 +235,15 @@
> // Ignore
> }
> }
> + errorDelay = 0;
> } catch (IOException x) {
> if (running) {
> log.error(sm.getString("endpoint.accept.fail"), x);
> + if (errorDelay == 0) {
> + errorDelay = 50;
> + } else if (errorDelay < 1600) {
> + errorDelay = errorDelay * 2;
> + }
> }
> } catch (NullPointerException npe) {
> if (running) {
>
>
>
> Thoughts / comments?
+1 - a bit of smarts in reducing redundant logging is usually a good thing.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Konstantin Kolinko <kn...@gmail.com>.
2011/2/21 Mark Thomas <ma...@apache.org>:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
>
> While better monitoring would/should have identified the problem sooner,
> it does demonstrate a problem with the acceptor threads in all three
> endpoints. If there is a system-level issue that causes the accept()
> call to always fail (such as hitting the ulimit) then the endpoint
> essentially enters a loop where it logs an error message for every
> iteration of the loop. This will result in many log messages per second.
>
> I'd like to do something about this. I was thinking of something along
> the lines of the following for each endpoint.
>
> Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
>
> Thoughts / comments?
>
+1
I thought that maybe the try/catch triggering this should cover accept
only and not processSocket, but actually that does not matter as
processSocket already catches Throwable.
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Filip Hanik - Dev Lists <de...@hanik.com>.
On 02/22/2011 12:59 PM, Mark Thomas wrote:
> On 22/02/2011 19:34, Filip Hanik - Dev Lists wrote:
>
>> Wouldn't you build this into the logging framework, instead of one
>> specific component?
>>
> You could, if you can find an efficient way to spot duplicate log
> messages and then differentiate correctly between when you want the
> duplicates and when you don't. I'm not sure how easy that would be.
> Suggestions welcome.
>
I'd probably wouldn't care so much about duplication as I would care
about logging frequency/amount per thread and have ways to adjust that.
> The other issue with the current code is that it is likely to chew up a
> large chunk of CPU time. Fixing the log mechanism won't fix that.
>
the maxConnections setting however, would fix this issue, as that forces
the system to back off.
So, I would have no problem adding a delay for that error. It makes the
product more stable, it would have to be added to all end points, as I
suspect they all do the same thing.
Filip
> Of course, the real solution is fix the ulimit issue in the first place
> but Tomcat's behaviour in this error condition seems sufficiently bad to
> justify some changes to handle it more gracefully.
>
> Mark
>
>
>> best
>> Filip
>>
>> On 02/21/2011 08:21 AM, Mark Thomas wrote:
>>
>>> The ASF Sonar installation managed to generate 46GB of identical log
>>> messages [1] today in the 8 hours it took to notice it was down.
>>>
>>> While better monitoring would/should have identified the problem sooner,
>>> it does demonstrate a problem with the acceptor threads in all three
>>> endpoints. If there is a system-level issue that causes the accept()
>>> call to always fail (such as hitting the ulimit) then the endpoint
>>> essentially enters a loop where it logs an error message for every
>>> iteration of the loop. This will result in many log messages per second.
>>>
>>> I'd like to do something about this. I was thinking of something along
>>> the lines of the following for each endpoint.
>>>
>>> Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
>>> ===================================================================
>>> --- java/org/apache/tomcat/util/net/JIoEndpoint.java (revision
>>> 1072939)
>>> +++ java/org/apache/tomcat/util/net/JIoEndpoint.java (working copy)
>>> @@ -183,9 +183,19 @@
>>> @Override
>>> public void run() {
>>>
>>> + int errorDelay = 0;
>>> +
>>> // Loop until we receive a shutdown command
>>> while (running) {
>>>
>>> + if (errorDelay> 0) {
>>> + try {
>>> + Thread.sleep(errorDelay);
>>> + } catch (InterruptedException e) {
>>> + // Ignore
>>> + }
>>> + }
>>> +
>>> // Loop if endpoint is paused
>>> while (paused&& running) {
>>> try {
>>> @@ -225,9 +235,15 @@
>>> // Ignore
>>> }
>>> }
>>> + errorDelay = 0;
>>> } catch (IOException x) {
>>> if (running) {
>>>
>>> log.error(sm.getString("endpoint.accept.fail"), x);
>>> + if (errorDelay == 0) {
>>> + errorDelay = 50;
>>> + } else if (errorDelay< 1600) {
>>> + errorDelay = errorDelay * 2;
>>> + }
>>> }
>>> } catch (NullPointerException npe) {
>>> if (running) {
>>>
>>>
>>>
>>> Thoughts / comments?
>>>
>>> Mark
>>>
>>>
>>> [1] http://pastebin.com/CrsujeW4
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: dev-help@tomcat.apache.org
>>>
>>>
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: dev-help@tomcat.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Mark Thomas <ma...@apache.org>.
On 22/02/2011 19:34, Filip Hanik - Dev Lists wrote:
> Wouldn't you build this into the logging framework, instead of one
> specific component?
You could, if you can find an efficient way to spot duplicate log
messages and then differentiate correctly between when you want the
duplicates and when you don't. I'm not sure how easy that would be.
Suggestions welcome.
The other issue with the current code is that it is likely to chew up a
large chunk of CPU time. Fixing the log mechanism won't fix that.
Of course, the real solution is fix the ulimit issue in the first place
but Tomcat's behaviour in this error condition seems sufficiently bad to
justify some changes to handle it more gracefully.
Mark
>
> best
> Filip
>
> On 02/21/2011 08:21 AM, Mark Thomas wrote:
>> The ASF Sonar installation managed to generate 46GB of identical log
>> messages [1] today in the 8 hours it took to notice it was down.
>>
>> While better monitoring would/should have identified the problem sooner,
>> it does demonstrate a problem with the acceptor threads in all three
>> endpoints. If there is a system-level issue that causes the accept()
>> call to always fail (such as hitting the ulimit) then the endpoint
>> essentially enters a loop where it logs an error message for every
>> iteration of the loop. This will result in many log messages per second.
>>
>> I'd like to do something about this. I was thinking of something along
>> the lines of the following for each endpoint.
>>
>> Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
>> ===================================================================
>> --- java/org/apache/tomcat/util/net/JIoEndpoint.java (revision
>> 1072939)
>> +++ java/org/apache/tomcat/util/net/JIoEndpoint.java (working copy)
>> @@ -183,9 +183,19 @@
>> @Override
>> public void run() {
>>
>> + int errorDelay = 0;
>> +
>> // Loop until we receive a shutdown command
>> while (running) {
>>
>> + if (errorDelay> 0) {
>> + try {
>> + Thread.sleep(errorDelay);
>> + } catch (InterruptedException e) {
>> + // Ignore
>> + }
>> + }
>> +
>> // Loop if endpoint is paused
>> while (paused&& running) {
>> try {
>> @@ -225,9 +235,15 @@
>> // Ignore
>> }
>> }
>> + errorDelay = 0;
>> } catch (IOException x) {
>> if (running) {
>>
>> log.error(sm.getString("endpoint.accept.fail"), x);
>> + if (errorDelay == 0) {
>> + errorDelay = 50;
>> + } else if (errorDelay< 1600) {
>> + errorDelay = errorDelay * 2;
>> + }
>> }
>> } catch (NullPointerException npe) {
>> if (running) {
>>
>>
>>
>> Thoughts / comments?
>>
>> Mark
>>
>>
>> [1] http://pastebin.com/CrsujeW4
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: dev-help@tomcat.apache.org
>>
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Filip Hanik - Dev Lists <de...@hanik.com>.
Wouldn't you build this into the logging framework, instead of one
specific component?
best
Filip
On 02/21/2011 08:21 AM, Mark Thomas wrote:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
>
> While better monitoring would/should have identified the problem sooner,
> it does demonstrate a problem with the acceptor threads in all three
> endpoints. If there is a system-level issue that causes the accept()
> call to always fail (such as hitting the ulimit) then the endpoint
> essentially enters a loop where it logs an error message for every
> iteration of the loop. This will result in many log messages per second.
>
> I'd like to do something about this. I was thinking of something along
> the lines of the following for each endpoint.
>
> Index: java/org/apache/tomcat/util/net/JIoEndpoint.java
> ===================================================================
> --- java/org/apache/tomcat/util/net/JIoEndpoint.java (revision 1072939)
> +++ java/org/apache/tomcat/util/net/JIoEndpoint.java (working copy)
> @@ -183,9 +183,19 @@
> @Override
> public void run() {
>
> + int errorDelay = 0;
> +
> // Loop until we receive a shutdown command
> while (running) {
>
> + if (errorDelay> 0) {
> + try {
> + Thread.sleep(errorDelay);
> + } catch (InterruptedException e) {
> + // Ignore
> + }
> + }
> +
> // Loop if endpoint is paused
> while (paused&& running) {
> try {
> @@ -225,9 +235,15 @@
> // Ignore
> }
> }
> + errorDelay = 0;
> } catch (IOException x) {
> if (running) {
> log.error(sm.getString("endpoint.accept.fail"), x);
> + if (errorDelay == 0) {
> + errorDelay = 50;
> + } else if (errorDelay< 1600) {
> + errorDelay = errorDelay * 2;
> + }
> }
> } catch (NullPointerException npe) {
> if (running) {
>
>
>
> Thoughts / comments?
>
> Mark
>
>
> [1] http://pastebin.com/CrsujeW4
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Mark,
On 2/21/2011 10:21 AM, Mark Thomas wrote:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
I've not really looked at how Tomcat does its logging, but do we have an
opportunity to do what, say, syslogd does when it emits messages like
"Last message repeated X times"?
If the logger could keep a reference to the last log message and do
comparisons, this would be possible. On the other hand, reducing the
performance of logging isn't a popular thing to do.
-chris
Re: Reaching ulimit values for open files can generate huge log files
Posted by Mark Thomas <ma...@apache.org>.
On 23/02/2011 11:47, Tim Funk wrote:
> Sorry - I meant to say - since the existing setSocketOptions() is in the
> try/catch block as accept(). Is it possible for a network client to send
> an ip packet to cause a failure and throw a SocketException while
> internally tomcat is setting each of the socket options? So the net
> effect is - the errorDelay value is set causing which makes endPoint
> fall asleep. Which could be a client induced DOS attack.
No problem, that is what I thought you meant :)
Mark
>
> So in the context above: user/client is someone on the network end, not
> the admin of the box. If the admin puts a config option in which causes
> setSocketOptions() to fail ... that is their problem.
>
> -Tim
>
>
> On 2/23/2011 5:48 AM, Mark Thomas wrote:
>> On 21/02/2011 17:33, Tim Funk wrote:
>>> Do you want to limit the try/catch scope to just
>>> serverSocketFactory.acceptSocket since setSocketOptions() can also throw
>>> IOException?
>>
>> A couple of people have mentioned this and while the current code would
>> be OK with a broader try/catch I like the idea of a limited try/catch
>> since that makes it obvious what the code is doing.
>>
>>> Is there a case where a client can induce an exception while
>>> setSocketOptions() is processing?
>>
>> I don't think so but let's not give them the opportunity.
>>
>> In terms of making this configurable, I'm minded not to initially. We
>> can always add configuration options if users request them later.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Tim Funk <fu...@apache.org>.
Sorry - I meant to say - since the existing setSocketOptions() is in the
try/catch block as accept(). Is it possible for a network client to send
an ip packet to cause a failure and throw a SocketException while
internally tomcat is setting each of the socket options? So the net
effect is - the errorDelay value is set causing which makes endPoint
fall asleep. Which could be a client induced DOS attack.
So in the context above: user/client is someone on the network end, not
the admin of the box. If the admin puts a config option in which causes
setSocketOptions() to fail ... that is their problem.
-Tim
On 2/23/2011 5:48 AM, Mark Thomas wrote:
> On 21/02/2011 17:33, Tim Funk wrote:
>> Do you want to limit the try/catch scope to just
>> serverSocketFactory.acceptSocket since setSocketOptions() can also throw
>> IOException?
>
> A couple of people have mentioned this and while the current code would
> be OK with a broader try/catch I like the idea of a limited try/catch
> since that makes it obvious what the code is doing.
>
>> Is there a case where a client can induce an exception while
>> setSocketOptions() is processing?
>
> I don't think so but let's not give them the opportunity.
>
> In terms of making this configurable, I'm minded not to initially. We
> can always add configuration options if users request them later.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Mark Thomas <ma...@apache.org>.
On 21/02/2011 17:33, Tim Funk wrote:
> Do you want to limit the try/catch scope to just
> serverSocketFactory.acceptSocket since setSocketOptions() can also throw
> IOException?
A couple of people have mentioned this and while the current code would
be OK with a broader try/catch I like the idea of a limited try/catch
since that makes it obvious what the code is doing.
> Is there a case where a client can induce an exception while
> setSocketOptions() is processing?
I don't think so but let's not give them the opportunity.
In terms of making this configurable, I'm minded not to initially. We
can always add configuration options if users request them later.
Mark
>
>
> -Tim
>
> On 2/21/2011 10:21 AM, Mark Thomas wrote:
>> The ASF Sonar installation managed to generate 46GB of identical log
>> messages [1] today in the 8 hours it took to notice it was down.
>>
>> While better monitoring would/should have identified the problem sooner,
>> it does demonstrate a problem with the acceptor threads in all three
>> endpoints. If there is a system-level issue that causes the accept()
>> call to always fail (such as hitting the ulimit) then the endpoint
>> essentially enters a loop where it logs an error message for every
>> iteration of the loop. This will result in many log messages per second.
>>
>> I'd like to do something about this. I was thinking of something along
>> the lines of the following for each endpoint.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Reaching ulimit values for open files can generate huge log files
Posted by Tim Funk <fu...@apache.org>.
Do you want to limit the try/catch scope to just
serverSocketFactory.acceptSocket since setSocketOptions() can also throw
IOException?
Is there a case where a client can induce an exception while
setSocketOptions() is processing?
-Tim
On 2/21/2011 10:21 AM, Mark Thomas wrote:
> The ASF Sonar installation managed to generate 46GB of identical log
> messages [1] today in the 8 hours it took to notice it was down.
>
> While better monitoring would/should have identified the problem sooner,
> it does demonstrate a problem with the acceptor threads in all three
> endpoints. If there is a system-level issue that causes the accept()
> call to always fail (such as hitting the ulimit) then the endpoint
> essentially enters a loop where it logs an error message for every
> iteration of the loop. This will result in many log messages per second.
>
> I'd like to do something about this. I was thinking of something along
> the lines of the following for each endpoint.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org