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-81609424...
> 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-81609424...
>
> 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(a)lists.fedorahosted.org
>
https://fedorahosted.org/mailman/listinfo/rhq-devel
_______________________________________________
rhq-devel mailing list
rhq-devel(a)lists.fedorahosted.org
https://fedorahosted.org/mailman/listinfo/rhq-devel