Alerts: woe is me...

Steven North swn at ocsystems.com
Mon Oct 24 05:50:24 UTC 2011


I'm back with some problems with RHQ (4.1) alert senders.  ;-)

To review, we have an alert sender that attempts to perform three steps 
when the alert fires:

- start a trace in an agent using a scheduleResourceOperation(),
- wait for an interval 1-10 minutes, and
- get a snapshot using getSnapshotReport().

Currently, we see problems in the server log and the scheduled operation 
seems to be delayed until the alert sender completes after getting the 
snapshot report. As you may recall, we were not able to wait for the 
scheduled operation to finish because we could not find the operation 
history after scheduling it, but the operation does eventually run to 
completion.  The net result is that we get a snapshot before we turn the 
trace on, which is not very useful.

Attached below is an excerpt from the server log which shows the errors 
we see when the alert sender runs.  It appears that the alert sender is 
holding a database lock, and that results in the scheduled operation not 
executing until the alert sender exits.

I looked at the Resource Operation sender and it just schedules the 
operation and leaves the alert notification status as deferred.  I can't 
find an example of an alert starting a resource operation and waiting 
for it to complete.

I have been trying to concoct a work-around to this issue but I have not 
succeeded.   Is there a way to "complete" a deferred alert notification 
from a "delayed" job in the RHQ server?  Can I schedule I delayed job 
from the alert notification to perform the snapshot and add it to the 
notification message?

Thanks in advance for any help.

Steve

-----------------------------------------------------------------------------------------------------------------------

2011-10-20 15:50:08,184 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: send:
2011-10-20 15:50:08,209 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: find enclosing: 13911
2011-10-20 15:50:08,210 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: lineage: /ecommerce/home.do < jboss_test < RTI Enterprise < 
v-ngi1
2011-10-20 15:50:08,210 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: start trace in 13901
2011-10-20 15:50:08,727 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: wait 5
2011-10-20 15:50:38,719 ERROR [org.quartz.core.ErrorLogger] An error 
occured while releasing trigger 
'org.rhq.enterprise.server.scheduler.jobs.CloudManagerJob.org.rhq.enterprise.server.scheduler.jobs.CloudManagerJob'
org.quartz.impl.jdbcjobstore.LockException: Failure obtaining db row 
lock: ERROR: canceling statement due to statement timeout [See nested 
exception: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout]
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.DBSemaphore.obtainLock(DBSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3753)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3722)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2805)
     at 
org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:305)
Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout
     at 
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
     at 
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
     at 
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:273)
     at 
org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:90)
     at 
org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:342)
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:92)
     ... 5 more
2011-10-20 15:50:58,313 WARN  
[org.hibernate.hql.ast.QueryTranslatorImpl] firstResult/maxResults 
specified with collection fetch; applying in memory!
2011-10-20 15:52:53,269 ERROR [org.quartz.impl.jdbcjobstore.JobStoreCMT] 
MisfireHandler: Error handling misfires: Failure obtaining db row lock: 
ERROR: canceling statement due to statement timeout
org.quartz.impl.jdbcjobstore.LockException: Failure obtaining db row 
lock: ERROR: canceling statement due to statement timeout [See nested 
exception: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout]
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.DBSemaphore.obtainLock(DBSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.doRecoverMisfires(JobStoreSupport.java:3124)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport$MisfireHandler.manage(JobStoreSupport.java:3887)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport$MisfireHandler.run(JobStoreSupport.java:3907)
Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout
     at 
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
     at 
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
     at 
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:273)
     at 
org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:90)
     at 
org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:342)
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:92)
     ... 4 more
2011-10-20 15:53:38,736 ERROR [org.quartz.core.ErrorLogger] An error 
occured while releasing trigger 
'org.rhq.enterprise.server.scheduler.jobs.CloudManagerJob.org.rhq.enterprise.server.scheduler.jobs.CloudManagerJob'
org.quartz.impl.jdbcjobstore.LockException: Failure obtaining db row 
lock: ERROR: canceling statement due to statement timeout [See nested 
exception: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout]
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.DBSemaphore.obtainLock(DBSemaphore.java:112)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3753)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3722)
     at 
org.quartz.impl.jdbcjobstore.JobStoreSupport.releaseAcquiredTrigger(JobStoreSupport.java:2805)
     at 
org.quartz.core.QuartzSchedulerThread.releaseTriggerRetryLoop(QuartzSchedulerThread.java:534)
     at 
org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:314)
Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement 
due to statement timeout
     at 
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
     at 
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
     at 
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
     at 
org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:273)
     at 
org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:90)
     at 
org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:342)
     at 
org.quartz.impl.jdbcjobstore.StdRowLockSemaphore.executeSQL(StdRowLockSemaphore.java:92)
     ... 6 more
2011-10-20 15:55:08,728 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: get snapshot 2011-10-20T20:50:08..2011-10-20T20:55:08 in 13901
2011-10-20 15:55:10,017 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: url = 
http://rhel5-64:7080/downloads/support/getDataInterval_300-13901-8160942464019255919.zip
2011-10-20 15:55:10,017 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: result RTI Alert:
   - Resource: /ecommerce/home.do < jboss_test < RTI Enterprise < v-ngi1
   - Condition 1: Average response time > 0.0ms
   - Date/Time: 2011/10/20 16:31:04 GMT-05:00
   - Details: 63.0ms
   - Action: trace
   - Interval: 5
   - Snapshot: [jboss_test < RTI Enterprise < v-ngi1] 
http://rhel5-64:7080/downloads/support/getDataInterval_300-13901-8160942464019255919.zip

2011-10-20 15:55:10,029 INFO  
[org.rhq.enterprise.server.util.concurrent.AlertSerializer] tid= 
2690315: alertDefinitionId=10131: releasing write lock after being 
locked for millis=301898
2011-10-20 15:55:10,029 INFO  
[org.rhq.enterprise.server.util.concurrent.AlertSerializer] tid= 
2690700: alertDefinitionId=10131: acquired write lock in millis=241924
2011-10-20 15:55:10,091 INFO  [com.ocsystems.rtiplugin.RtiAlertSender] 
RTI Alert: send:



More information about the rhq-devel mailing list