You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "Gary Tully (Jira)" <ji...@apache.org> on 2021/10/29 16:17:00 UTC
[jira] [Comment Edited] (ARTEMIS-3489) JdbcLeaseLockTest fails
sporadically in CI
[ https://issues.apache.org/jira/browse/ARTEMIS-3489?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17436056#comment-17436056 ]
Gary Tully edited comment on ARTEMIS-3489 at 10/29/21, 4:16 PM:
----------------------------------------------------------------
It looks like the problem is the lease timeout is just too low, the update with 10ms duration calculated from current time expires before the statement to execute is processed and it then fails the update condition.
the test seems ok, but I think we need to push up the lease duration.
at time: 16:48:08,306, before the update execute the expirationTime 16:48:08.114 is behind!
{code:java}
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.PoolingDataSource$PoolGuardConnectionWrapper@662936a.prepareStatement(UPDATE NODE_MANAGER_STORE SET HOLDER_EXPIRATION_TIME = ? WHERE HOLDER_ID = ? AND HOLDER_EXPIRATION_TIME IS NOT NULL AND ? >= HOLDER_EXPIRATION_TIME AND ? > CURRENT_TIMESTAMP AND ID = 1) = org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.PoolingDataSource$PoolGuardConnectionWrapper@662936a.prepareStatement(SELECT CURRENT_TIMESTAMP FROM NODE_MANAGER_STORE) = org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611.executeQuery() = org.apache.commons.dbcp2.DelegatingResultSet@30cd738c
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.next() = true
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.getTimestamp(1) = 2021-10-29 16:48:08.104
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.close()
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611.close()
[main] 16:48:08,306 DEBUG [org.apache.activemq.artemis.core.server.impl.jdbc.JdbcLeaseLock] [LIVE] 491cf07b-65b3-43b9-99a8-072c99e09fbe is renewing lock with expirationTime = 2021-10-29 16:48:08.114
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(1, 2021-10-29 16:48:08.114)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setString(2, 491cf07b-65b3-43b9-99a8-072c99e09fbe)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(3, 2021-10-29 16:48:08.114)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(4, 2021-10-29 16:48:08.114)
[main] 16:48:08,312 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.executeUpdate() = 0
{code}
was (Author: gtully):
It looks like the problem is the lease timeout is just too low, the update with 10ms duration calculated from current time expires before the statement to execute is processed and it then fails the update condition.
the test seems ok, but I think we need to push up the lease duration.
{code:java}
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.PoolingDataSource$PoolGuardConnectionWrapper@662936a.prepareStatement(UPDATE NODE_MANAGER_STORE SET HOLDER_EXPIRATION_TIME = ? WHERE HOLDER_ID = ? AND HOLDER_EXPIRATION_TIME IS NOT NULL AND ? >= HOLDER_EXPIRATION_TIME AND ? > CURRENT_TIMESTAMP AND ID = 1) = org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.PoolingDataSource$PoolGuardConnectionWrapper@662936a.prepareStatement(SELECT CURRENT_TIMESTAMP FROM NODE_MANAGER_STORE) = org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611.executeQuery() = org.apache.commons.dbcp2.DelegatingResultSet@30cd738c
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.next() = true
[main] 16:48:08,104 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.getTimestamp(1) = 2021-10-29 16:48:08.104
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingResultSet@30cd738c.close()
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@7f4c8611.close()
[main] 16:48:08,306 DEBUG [org.apache.activemq.artemis.core.server.impl.jdbc.JdbcLeaseLock] [LIVE] 491cf07b-65b3-43b9-99a8-072c99e09fbe is renewing lock with expirationTime = 2021-10-29 16:48:08.114
[main] 16:48:08,306 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(1, 2021-10-29 16:48:08.114)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setString(2, 491cf07b-65b3-43b9-99a8-072c99e09fbe)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(3, 2021-10-29 16:48:08.114)
[main] 16:48:08,307 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.setTimestamp(4, 2021-10-29 16:48:08.114)
[main] 16:48:08,312 TRACE [org.apache.activemq.artemis.jdbc.store.drivers.JDBCConnectionProvider] org.apache.commons.dbcp2.DelegatingPreparedStatement@5735f981.executeUpdate() = 0
{code}
> JdbcLeaseLockTest fails sporadically in CI
> ------------------------------------------
>
> Key: ARTEMIS-3489
> URL: https://issues.apache.org/jira/browse/ARTEMIS-3489
> Project: ActiveMQ Artemis
> Issue Type: Test
> Affects Versions: 2.18.0
> Reporter: Robbie Gemmell
> Priority: Major
>
> JdbcLeaseLockTest fails sporadically in CI:
> E.g:
> [https://app.travis-ci.com/github/apache/activemq-artemis/jobs/538004665#L3201]
> [https://github.com/apache/activemq-artemis/runs/3531185223?check_suite_focus=true#step:5:2094]
> https://github.com/apache/activemq-artemis/runs/3507926162?check_suite_focus=true#step:5:2256
--
This message was sent by Atlassian Jira
(v8.3.4#803005)