Alerts: woe is me...

Steven North swn at ocsystems.com
Wed Oct 26 15:33:36 UTC 2011


Mazz,

Thanks.  I wound up doing essentially what you suggested, though I just 
used a regular Thread to do the waiting and the getSnapshotReport() 
call.  Do you think there is any advantage to using a Quartz-scheduled 
job versus a plain Thread that waits?

I'll see if I can come up with an example.

Steve

On 10/26/2011 5:39 AM, John Mazzitelli wrote:
> Steve,
>
> I can't explain why that error happens, but it is happening inside the
> Quartz scheduler. For some reason, Quartz is bombing out.
>
> I can't say we've ever seen this behavior before. Would you be able to
> write up a simple test case/replication procedures and open a bugzilla
> bug report?
>
> https://bugzilla.redhat.com/enter_bug.cgi?product=RHQ%20Project
>
> Even if it means creating a test alert server plugin that just sleeps
> for N seconds/minutes or whatever to simulate a long running alert
> notification but still shows the problem you see.
>
> NOTE: one option for a workaround would be to not block in your alert
> sender code. The:
>
> - wait for an interval 1-10 minutes, and
>
> part. Remember that server plugins have full access to the server API -
> including the Quartz engine (see our SchedulerBean -
> LookupUtil.getSchedulerBean()). You could schedule a one-time job to
> trigger in the future (say, schedule a job for 1-10 minutes in the
> future). Your alert sender would exit immediately and quartz would then
> spawn the job later - in your quartz job, you would then
>
> - get a snapshot using getSnapshotReport().
>
> I have no idea if that is helpful or not - but I figured I would throw
> it out there.
>
> --
> John Mazz
>
>
> On Sun, 2011-10-23 at 22:50 -0700, Steven North wrote:
>> 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:
>>
>> _______________________________________________
>> rhq-devel mailing list
>> rhq-devel at lists.fedorahosted.org
>> https://fedorahosted.org/mailman/listinfo/rhq-devel
>
> _______________________________________________
> rhq-devel mailing list
> rhq-devel at lists.fedorahosted.org
> https://fedorahosted.org/mailman/listinfo/rhq-devel



More information about the rhq-devel mailing list