Re: [mod-security-users] console memory usage grows indefinintely ?

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Ivan wrote: 

> Are there any interesting messages in the debug log around that time?

There are.  At 6am proper there is both an SQL warning and ERROR.  After
that is when I get the out of memory errors.

The "no row found" warnings seem to be fairly common throughout my logs.
The "SEVERE: Could not close JDBC Connection" error only seems to occur at
6am.

Ivan wrote:
> If it became unresponsive around 6am you may want to try removing the
> following line from your configuration

Ohh, good call.  To confirm that job is the issue, I started it back up at
8:50am, and scheduled the deleteTransactions job to run at 9am, and right on
schedule it became unresponsive again.  So that definitely seems to be the
culprit.

Is it a permanent solution to just disable that job?

Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #5
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #5 for Sat Dec 20 06:00:00 CST 2008 (1229774400000)
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #2
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #2 for Fri Dec 19 06:10:00 CST 2008 (1229688600000)
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #3
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #3 for Fri Dec 19 06:01:00 CST 2008 (1229688060000)
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #4
Dec 19, 2008 6:00:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #4 for Fri Dec 19 06:01:00 CST 2008 (1229688060000)
Dec 19, 2008 6:00:00 AM org.springframework.jdbc.core.JdbcTemplate
throwExceptionOnWarningIfNotIgnoringWarnings
WARNING: SQLWarning ignored: java.sql.SQLWarning: No row was found for
FETCH, UPDATE or DELETE; or the result of a query is an empty table.
Dec 19, 2008 6:00:08 AM org.springframework.jdbc.datasource.DataSourceUtils
releaseConnection
SEVERE: Could not close JDBC Connection
java.sql.SQLException: Already closed.
        at
org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:77)
        at
org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.close(Pooli
ngDriver.java:240)
        at
org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(Data
SourceUtils.java:277)
        at
org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSo
urceUtils.java:238)
        at
org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:491)
        at
org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:528)
        at
org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:561)
        at
org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:579)
        at
org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:589)
        at
org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:609)
        at
org.springframework.jdbc.core.JdbcTemplate.queryForList(JdbcTemplate.java:67
4)
        at
com.thinkingstone.console.model.JdbcConsole.deleteTransactions(Unknown
Source)
        at
com.thinkingstone.console.ConsoleComponent.deleteTransactions(Unknown
Source)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at com.thinkingstone.chronos.ExecWrapper.run(Unknown Source)
        at
com.thinkingstone.chronos.ChronosScheduler$TaskExecutor.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
Dec 19, 2008 6:01:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #3
Dec 19, 2008 6:01:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #3 for Fri Dec 19 06:02:00 CST 2008 (1229688120000)
Dec 19, 2008 6:01:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #4
Dec 19, 2008 6:01:00 AM com.thinkingstone.chronos.ChronosScheduler
_scheduleTask
INFO: Scheduled task #4 for Fri Dec 19 06:02:00 CST 2008 (1229688120000)
Dec 19, 2008 6:01:07 AM org.mortbay.util.ThreadedServer$Acceptor run
WARNING: EXCEPTION
java.lang.OutOfMemoryError: Java heap space
        at java.io.ByteArrayOutputStream.<init>(Unknown Source)
        at com.sun.net.ssl.internal.ssl.OutputRecord.<init>(Unknown Source)
        at com.sun.net.ssl.internal.ssl.OutputRecord.<init>(Unknown Source)
        at com.sun.net.ssl.internal.ssl.AppOutputStream.<init>(Unknown
Source)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.init(Unknown Source)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.<init>(Unknown Source)
        at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(Unknown
Source)
        at
org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:432)
        at
org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:432)
        at
org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:631)
Dec 19, 2008 6:01:08 AM org.mortbay.util.ThreadedServer$Acceptor run
WARNING: EXCEPTION
java.lang.OutOfMemoryError: Java heap space
Dec 19, 2008 6:01:08 AM org.mortbay.http.HttpConnection exception
WARNING: null null null
java.lang.OutOfMemoryError: Java heap space
Dec 19, 2008 6:02:00 AM com.thinkingstone.chronos.ChronosScheduler run
INFO: Executing task #3

- -----Original Message-----
From: Ivan Ristic [mailto:iva...@gm...] 
Sent: Thursday, December 18, 2008 1:18 PM
To: Kyle Bresin
Cc: mod...@li...
Subject: Re: [mod-security-users] console memory usage grows indefinintely ?

Are there any interesting messages in the debug log around that time?
An out of memory condition is typically accompanied by an
OutOfMemoryException.

If it became unresponsive around 6am you may want to try removing the
following line from your configuration:

ScheduleMethod "0 6 * * *" "deleteTransactions"

On Thu, Dec 18, 2008 at 7:08 PM, Kyle Bresin <Kb...@in...>
wrote:
>
> It crashed at exactly the same time last night (this morning).
>
> I don't think my memory allocation hypothesis is the best explanation any
> more.
>
> I'm going to do a clean install and see if that makes the problem
disappear.
>
> Thanks for the help!
>
> kyle.
>
> -----Original Message-----
> From: Ivan Ristic [mailto:iva...@gm...]
> Sent: Wednesday, December 17, 2008 1:07 PM
> To: Kyle Bresin
> Cc: mod...@li...
> Subject: Re: [mod-security-users] console memory usage grows indefinintely
?
>
> Are you running any reports at all? If yes, try disabling them.
>
> I've run the very same version of the console with > 1M transactions
> (a hundred or so open at any one time) with no reports and no
> problems.
>
>
> On Wed, Dec 17, 2008 at 6:56 PM, Kyle Bresin <Kb...@in...>
> wrote:
>> Ivan Ristic wrote:
>>
>>> It's not unusual for any Java application (the Console is written in
>>> Java) to expand memory allocation until it reaches the maximum. The
>>> JVM typically releases memory only when it runs out.
>>
>> But there is the fact that the console become unresponsive just after it
>> seemed to have reached the point of allocating up to the maximum?
>>
>> 6am is definitely not our busy time...
>>
>> Ivan Ristic wrote:
>>
>>> The only reason I know for the Console becoming unresponsive is if you
>>> have a large amount of events in the database. How many do you have?
>>
>> ij> SELECT alert_status, count(1) from alerts group by alert_status;
>> ALERT_STATUS                    |2
>> --------------------------------------------
>> CLOSED                          |44356
>> OPEN                            |24
>>
>>
>> If it was just the pure amount of rows in the database, I'm confused why
>> restarting it would solve the issue for 24 hours?
>>
>> Thanks for the help!
>>
>> kyle.
>>
>> -----Original Message-----
>> From: Ivan Ristic [mailto:iva...@gm...]
>> Sent: Wednesday, December 17, 2008 12:01 PM
>> To: Kyle Bresin
>> Cc: mod...@li...
>> Subject: Re: [mod-security-users] console memory usage grows
> indefinintely?
>>
>> It's not unusual for any Java application (the Console is written in
>> Java) to expand memory allocation until it reaches the maximum. The
>> JVM typically releases memory only when it runs out.
>>
>> The only reason I know for the Console becoming unresponsive is if you
>> have a large amount of events in the database. How many do you have?
>>
>>
>> On Wed, Dec 17, 2008 at 5:25 PM, Kyle Bresin <Kb...@in...>
>> wrote:
>>> -----BEGIN PGP SIGNED MESSAGE-----
>>> Hash: SHA256
>>>
>>>
>>> I am running modsecurity-console 1.0.5 on a linux box with a 1.6.0 jre.
>>>
>>> I have two sensors configured.
>>>
>>> The console seems to lock up every 24 hours or so.
>>>
>>> I upped it's memory limit, and wrote a monitor to watch how much it was
>>> using it.
>>>
>>> Regardless of the number of open alerts it seems to slowly eat more and
>> more
>>> memory throughout the day, until it crashes.
>>>
>>> I have read the tuning document, and have gone through and eliminated a
>> lot
>>> of false positives until the sensor only has an average of 30 open
alerts
>> at
>>> a time.
>>>
>>> I've also set auto-pruning of alerts to 3600 seconds.
>>>
>>> Here is my line from the startup script to up the memory:
>>> INSTALL4J_ADD_VM_PARAMS="-Xms32M -Xmx128M
>> -Dderby.storage.pageCacheSize=4000
>>> -Dderby.storage.pageSize=16384"
>>>
>>> I suppose I could give it more, but I'm not convinced that that wouldn't
>>> just be extending the time it takes to crash...
>>>
>>> Here's a snapshot of the memory usage:
>>>
>>> 20081216 10:00 MEM: Free 26928 KB, Allocated 77388 KB, Max 129664 KB
>>> 20081216 11:00 MEM: Free 12622 KB, Allocated 77388 KB, Max 129664 KB
>>> 20081216 12:00 MEM: Free 33425 KB, Allocated 93108 KB, Max 129664 KB
>>> 20081216 13:00 MEM: Free 32796 KB, Allocated 93108 KB, Max 129664 KB
>>> 20081216 14:00 MEM: Free 24003 KB, Allocated 93108 KB, Max 129664 KB
>>> 20081216 15:00 MEM: Free 13305 KB, Allocated 93108 KB, Max 129664 KB
>>> 20081216 16:00 MEM: Free 35429 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 17:00 MEM: Free 26868 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 18:00 MEM: Free 14169 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 19:00 MEM: Free 5358 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 20:00 MEM: Free 35605 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 21:00 MEM: Free 28132 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 22:00 MEM: Free 21152 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081216 23:00 MEM: Free 7548 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081217 00:00 MEM: Free 38969 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081217 01:00 MEM: Free 26037 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081217 02:00 MEM: Free 17908 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081217 03:00 MEM: Free 9407 KB, Allocated 98464 KB, Max 129664 KB
>>> 20081217 04:00 MEM: Free 34910 KB, Allocated 99968 KB, Max 129664 KB
>>> 20081217 05:00 MEM: Free 21984 KB, Allocated 99968 KB, Max 129664 KB
>>> 20081217 06:00 MEM: Free 7991 KB, Allocated 116212 KB, Max 129664 KB
>>> 20081217 06:05 modsec-console unresponsive
>>>
>>> RESTARTED
>>>
>>> 20081217 08:25 MEM: Free 9433 KB, Allocated 32448 KB, Max 129664 KB
>>> 20081217 09:00 MEM: Free 19445 KB, Allocated 45736 KB, Max 129664 KB
>>> 20081217 10:00 MEM: Free 8392 KB, Allocated 45736 KB, Max 129664 KB
>>> 20081217 11:00 MEM: Free 11064 KB, Allocated 48568 KB, Max 129664 KB
>>>
>>> Anyone have any explanations for why the console would need an
increasing
>>> amount of memory when the number of alerts is fairly static?
>>>
>>> Right now I'm considering just restarting it nightly, which makes me
>>> bristle, but it's the only idea I have.  Less crude suggestions would be
>>> appreciated.
>>>
>>> Thanks for reading.
>>>
>>> kyle.
>>>
>>> Kyle Bresin
>>> Systems Security Architect
>>> kb...@in...
>>>
>>>
>>> -----BEGIN PGP SIGNATURE-----
>>> Version: 9.9.0 (Build 397)
>>> Charset: utf-8
>>>
>>> wsBVAwUBSUk2EDugWmOSG/gnAQhdXQf+KRXMK7GM+Ra2wClUN+qBipXTwV9lp8TZ
>>> V9V1leQRva+96rUXbHNjoqppsC47kM0pFMZLeQnep+A5rhRjXKo+L6TBhnYQPRjM
>>> TOHcymwjE3HWB9E1VHBsgBchC9OS1XWURZNdYRlmj7X7F32aJMpiMxMrSe4wkCzL
>>> f6A1rnG9MdbVYgqLG/0pYv8as/JoL6m3FJW/XMBRG4BkNzApXNI1tmMgxp0BYEsC
>>> ffvU/AxFB6uaE8slGde0xNTr2pV72JD99iLp7OfAzHE46J2Loc+eyOBxUQjA8+KO
>>> rPTdIiAlgq/DPBt4cO0wBIKgSyAzJFxX/GTpPrUGyC8mBnYIXKi+/g==
>>> =ytPP
>>> -----END PGP SIGNATURE-----
>>>
>>>
>>>
>>
>
----------------------------------------------------------------------------
>> --
>>> SF.Net email is Sponsored by MIX09, March 18-20, 2009 in Las Vegas,
>> Nevada.
>>> The future of the web can't happen without you.  Join us at MIX09 to
help
>>> pave the way to the Next Web now. Learn more and register at
>>>
>>
>
http://ad.doubleclick.net/clk;208669438;13503038;i?http://2009.visitmix.com/
>>> _______________________________________________
>>> mod-security-users mailing list
>>> mod...@li...
>>> https://lists.sourceforge.net/lists/listinfo/mod-security-users
>>>
>>
>>
>>
>> --
>> Ivan Ristic
>>
>
>
>
> --
> Ivan Ristic
>

- -- 
Ivan Ristic
-----BEGIN PGP SIGNATURE-----
Version: 9.9.0 (Build 397)
Charset: utf-8

wsBVAwUBSUu3zzugWmOSG/gnAQgX9AgAmV8OMijZtGdzhylw5LlkRR3PYdFrgoTz
V/U/3hGvjZKRAVQPQGmYjFLwW9pyQs0qvLdtn/s57Id1gNHc8RiIYHr5efvfkOby
S/eZFPS2M6+k1Vn21BYp7uFBr6mSyQ7g8ymjJBP6KPaGhF6qq1Qpk56Kreo/fDi/
SBroEZ9hAcMLxA1fKhr8QOCUgyyYhveYDR6suO/VQ+T9jf7HPNSXLLZgpvfVezQp
CquGh6W4g4CP9sK4RSUhwBs8vTW3aE8Qi4J+KZNZRw+Zd3H4g18gPKi55YGGRgvn
kCMorZ46Zd9tbFfn/+zx6poNWfRfV+Z/H/choJf2zNMEDT1EgtzjKA==
=iR3N
-----END PGP SIGNATURE-----