code.onehippo.org is currently readonly. We are migrating to code.bloomreach.com, please continue working there on Monday 14/12. See: https://docs.bloomreach.com/display/engineering/GitLab

Commit 4fdb9278 authored by Ard Schrijvers's avatar Ard Schrijvers

REPO-1811 Improve exception handling and logging

parent 547542ef
......@@ -25,6 +25,7 @@ import java.util.concurrent.ScheduledExecutorService;
import org.onehippo.cms7.services.lock.Lock;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.cms7.services.lock.LockManagerException;
import org.slf4j.Logger;
import static java.util.concurrent.TimeUnit.SECONDS;
......@@ -49,13 +50,13 @@ public abstract class AbstractLockManager implements InternalLockManager {
protected abstract MutableLock createLock(String key, String threadName, int refreshRateSeconds) throws LockException;
protected abstract void releasePersistedLock(String key, String threadName) throws LockException;
protected abstract void releasePersistedLock(String key, String threadName);
protected abstract void abortPersistedLock(String key) throws LockException;
protected abstract void abortPersistedLock(String key) throws LockManagerException;
protected abstract boolean containsLock(String key) throws LockException;
protected abstract boolean containsLock(String key) throws LockManagerException;
protected abstract List<Lock> retrieveLocks() throws LockException;
protected abstract List<Lock> retrieveLocks() throws LockManagerException;
public AbstractLockManager() {
scheduledExecutorService = Executors.newScheduledThreadPool(1);
......@@ -103,25 +104,29 @@ public abstract class AbstractLockManager implements InternalLockManager {
}
@Override
public synchronized void unlock(final String key) throws LockException {
public synchronized void unlock(final String key) {
checkLive();
validateKey(key);
final MutableLock lock = localLocks.get(key);
if (lock == null) {
// note there can still be a database lock : The lock might be owned by a different cluster node
throw new LockException(String.format("No lock present for '{}'", key));
getLogger().error("Lock '{}' does not exist or this cluster node does not contain the lock hence a thread from " +
"this JVM cannot unlock it", key);
return;
}
final Thread lockThread = lock.getThread().get();
if (lockThread == null || !lockThread.isAlive()) {
getLogger().warn("Thread '{}' that created lock for '{}' has stopped without releasing the lock. Removing lock now",
getLogger().error("Thread '{}' that created lock for '{}' has stopped without releasing the lock. The Thread " +
"should had invoked #unlock. Removing lock now",
lock.getLockOwner(), key, Thread.currentThread().getName());
releasePersistedLock(key, lockThread.getName());
localLocks.remove(key);
return;
}
if (lockThread != Thread.currentThread()) {
throw new LockException(String.format("Thread '%s' cannot unlock '%s' because lock owned by '%s'", Thread.currentThread().getName(), key,
lockThread.getName()));
getLogger().error("Thread '{}' cannot unlock '{}' because lock owned by '{}'. Thread '{}' should never had " +
"invoked #unlock({}), this is an end implementation error.", Thread.currentThread().getName(), key,
lockThread.getName(), Thread.currentThread().getName(), key);
return;
}
lock.decrement();
if (lock.getHoldCount() < 0) {
......@@ -141,7 +146,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
}
@Override
public synchronized void abort(final String key) throws LockException {
public synchronized void abort(final String key) throws LockManagerException {
checkLive();
validateKey(key);
final MutableLock localLock = localLocks.get(key);
......@@ -161,7 +166,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
} catch (SecurityException e) {
String msg = String.format("Thread '%s' is not allowed to be interrupted. Can't abort '%s'", thread.getName(), key);
getLogger().warn(msg);
throw new LockException(msg);
throw new IllegalStateException(msg);
}
}
......@@ -169,7 +174,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
}
@Override
public synchronized boolean isLocked(final String key) throws LockException {
public synchronized boolean isLocked(final String key) throws LockManagerException {
checkLive();
validateKey(key);
expungeNeverUnlockedLocksFromStoppedThreads();
......@@ -177,7 +182,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
}
@Override
public synchronized List<Lock> getLocks() throws LockException {
public synchronized List<Lock> getLocks() throws LockManagerException {
checkLive();
expungeNeverUnlockedLocksFromStoppedThreads();
return retrieveLocks();
......@@ -202,7 +207,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
while (iterator.hasNext()) {
final Map.Entry<String, MutableLock> next = iterator.next();
getLogger().warn("Lock '{}' owned by '{}' was never unlocked. Removing the lock now.", next.getKey(), next.getValue().getLockOwner());
tryReleaseLock(next.getKey(), next.getValue().getLockThread());
releasePersistedLock(next.getKey(), next.getValue().getLockThread());
iterator.remove();
}
}
......@@ -213,18 +218,6 @@ public abstract class AbstractLockManager implements InternalLockManager {
}
}
private synchronized void tryReleaseLock(final String key, final String lockThread) {
try {
releasePersistedLock(key, lockThread);
} catch (LockException e) {
if (getLogger().isDebugEnabled()) {
getLogger().warn("Could not release '{}'", key, e);
} else {
getLogger().warn("Could not release '{}' : {}", key, e.toString());
}
}
}
public synchronized void expungeNeverUnlockedLocksFromStoppedThreads() {
final Iterator<Map.Entry<String, MutableLock>> iterator = localLocks.entrySet().iterator();
while (iterator.hasNext()) {
......@@ -233,7 +226,7 @@ public abstract class AbstractLockManager implements InternalLockManager {
if (lock.getThread().get() == null || !lock.getThread().get().isAlive()) {
getLogger().warn("Lock '{}' with lockOwner '{}' was present but the Thread that created the lock already stopped. " +
"Removing the lock now", next.getKey(), lock.getLockOwner());
tryReleaseLock(next.getKey(), next.getValue().getLockThread());
releasePersistedLock(next.getKey(), next.getValue().getLockThread());
iterator.remove();
}
}
......
......@@ -22,11 +22,13 @@ import java.sql.SQLException;
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import java.util.stream.Stream;
import javax.sql.DataSource;
import org.onehippo.cms7.services.lock.Lock;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.cms7.services.lock.LockManagerException;
import org.onehippo.repository.lock.AbstractLockManager;
import org.onehippo.repository.lock.MutableLock;
import org.slf4j.Logger;
......@@ -156,7 +158,7 @@ public class DbLockManager extends AbstractLockManager {
}
@Override
protected synchronized void releasePersistedLock(final String key, final String threadName) throws LockException {
protected synchronized void releasePersistedLock(final String key, final String threadName) {
Connection connection = null;
boolean originalAutoCommit = false;
try {
......@@ -173,32 +175,29 @@ public class DbLockManager extends AbstractLockManager {
selectStatement.setString(1, key);
ResultSet resultSet = selectStatement.executeQuery();
if (!resultSet.next()) {
String msg = String.format("Lock '%s' cannot be released by '%s' because lock does not exist", key, threadName);
log.warn(msg);
throw new LockException(msg);
log.error("Database Lock '{}' cannot be released by '{}' and cluster '{}' because lock does not exist",
key, threadName, clusterNodeId);
return;
} else {
String msg = String.format("Lock '%s' cannot be released for thread '%s' because lock is not owned.", key, threadName);
log.warn(msg);
throw new LockException(msg);
log.error("Database Lock '{}' cannot be released for thread '{}' and cluster '{}' because lock is not owned.",
key, threadName, clusterNodeId);
return;
}
}
log.info("Successfully released '{}'", key);
} catch (SQLException e) {
String msg = String.format("Cannot unlock '%s'.", key);
if (log.isDebugEnabled()) {
log.info(msg, e);
} else {
log.info(msg + " : {}", e.toString());
}
throw new LockException(msg, e);
final String msg = String.format("Unlocking Database Lock '%s' for thread '%s' and cluster '%s' failed.", key, threadName, clusterNodeId, e);
log.error(msg);
// we do not want to throw a checked exception for #unlock because that would mean code flow that in the finally block
// wants to unlock would always have to catch an exception....with which a developer can't do much
throw new RuntimeException(msg, e);
} finally {
close(connection, originalAutoCommit);
}
}
@Override
protected synchronized void abortPersistedLock(final String key) throws LockException {
protected synchronized void abortPersistedLock(final String key) throws LockManagerException {
Connection connection = null;
boolean originalAutoCommit = false;
try {
......@@ -215,21 +214,16 @@ public class DbLockManager extends AbstractLockManager {
}
log.info("Successfully changed status to abort for '{}'", key);
} catch (SQLException e) {
String msg = String.format("Cannot abort '%s'.", key);
if (log.isDebugEnabled()) {
log.info(msg, e);
} else {
log.info(msg + " : {}", e.toString());
}
throw new LockException(msg, e);
final String msg = String.format("Aborting Database Lock '%s' failed.", key);
log.error(msg, e);
throw new LockManagerException(msg, e);
} finally {
close(connection, originalAutoCommit);
}
}
@Override
protected synchronized boolean containsLock(final String key) throws LockException {
protected synchronized boolean containsLock(final String key) throws LockManagerException {
try (Connection connection = dataSource.getConnection()) {
final PreparedStatement selectStatement = connection.prepareStatement(SELECT_STATEMENT);
selectStatement.setString(1, key);
......@@ -243,19 +237,14 @@ public class DbLockManager extends AbstractLockManager {
log.debug("Found database row for '{}' with locked = {}", key, locked);
return locked;
} catch (SQLException e) {
String msg = String.format("Could not query for '%s'.", key);
if (log.isDebugEnabled()) {
log.info(msg, e);
} else {
log.info(msg + " : {}", e.toString());
}
throw new LockException(msg, e);
final String msg = String.format("Exception while checking lock for '%s'. Return false.", key);
log.error(msg, e);
throw new LockManagerException(msg, e);
}
}
@Override
protected synchronized List<Lock> retrieveLocks() throws LockException {
protected synchronized List<Lock> retrieveLocks() throws LockManagerException {
try (Connection connection = dataSource.getConnection()) {
final PreparedStatement selectStatement = connection.prepareStatement(ALL_LOCKED_STATEMENT);
ResultSet resultSet = selectStatement.executeQuery();
......@@ -275,14 +264,9 @@ public class DbLockManager extends AbstractLockManager {
}
return locks;
} catch (SQLException e) {
String msg = String.format("Could retrieve locks");
if (log.isDebugEnabled()) {
log.info(msg, e);
} else {
log.info(msg + " : {}", e.toString());
}
throw new LockException(msg, e);
final String msg = "Exception while retrieving database locks. Return empty list";
log.error(msg, e);
throw new LockManagerException(msg, e);
}
}
}
......@@ -20,6 +20,7 @@ import java.util.List;
import org.onehippo.cms7.services.lock.Lock;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.cms7.services.lock.LockManagerException;
import org.onehippo.repository.lock.AbstractLockManager;
import org.onehippo.repository.lock.MutableLock;
import org.slf4j.Logger;
......@@ -44,22 +45,22 @@ public class MemoryLockManager extends AbstractLockManager {
}
@Override
protected void releasePersistedLock(final String key, final String threadName) throws LockException {
protected void releasePersistedLock(final String key, final String threadName) {
// no persistent lock needs to be removed so nothing to do
}
@Override
protected void abortPersistedLock(final String key) throws LockException {
protected void abortPersistedLock(final String key) throws LockManagerException {
// no persistent lock needs to be aborted so nothing else is needed
}
@Override
protected synchronized boolean containsLock(final String key) throws LockException {
protected synchronized boolean containsLock(final String key) throws LockManagerException {
return getLocalLocks().containsKey(key);
}
@Override
protected synchronized List<Lock> retrieveLocks() throws LockException {
protected synchronized List<Lock> retrieveLocks() throws LockManagerException {
return new ArrayList<>(getLocalLocks().values());
}
}
......@@ -20,7 +20,7 @@ import java.util.concurrent.ExecutionException;
import org.junit.Before;
import org.junit.Test;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.repository.lock.MutableLock;
import org.onehippo.cms7.services.lock.LockManagerException;
import org.onehippo.repository.lock.memory.MemoryLockManager;
import org.onehippo.testutils.log4j.Log4jInterceptor;
......@@ -69,10 +69,16 @@ public class MemoryLockManagerTest {
public void other_thread_cannot_unlock_() throws Exception {
memoryLockManager.lock("123");
Thread lockThread = new Thread(() -> {
try {
// other thread should not successfully unlock and we expect an error to be logged
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class).build()) {
memoryLockManager.unlock("123");
} catch (LockException e) {
// expected
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread '"+Thread.currentThread().getName()+"' should never had invoked #unlock(123)")));
}
// "123" should still be locked
try {
assertTrue(memoryLockManager.isLocked("123"));
} catch (LockManagerException e) {
fail("#isLocked check failed");
}
});
......@@ -112,12 +118,21 @@ public class MemoryLockManagerTest {
// give time to the lockThread
Thread.sleep(100);
try {
// other thread should not successfully unlock and we expect an error to be logged
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class).build()) {
memoryLockManager.unlock("123");
fail("Main thread should not be able to unlock");
} catch (LockException e) {
// expected
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread 'main' should never had invoked #unlock(123)")));
}
// trying again should result in same error
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class).build()) {
memoryLockManager.unlock("123");
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread 'main' should never had invoked #unlock(123)")));
}
// "123" should still be locked
assertTrue(memoryLockManager.isLocked("123"));
}
@Test
......
......@@ -32,12 +32,12 @@ public class RepositoryLoggerTest extends RepositoryTestCase {
@Before
public void setUp() throws Exception {
super.setUp();
removeNode("/hippo:log/default");
removeNode("/hippo:log/" + RepositoryLogger.getClusterNodeId(session));
}
@After
public void tearDown() throws Exception {
removeNode("/hippo:log/default");
removeNode("/hippo:log/" + RepositoryLogger.getClusterNodeId(session));
super.tearDown();
}
......@@ -58,7 +58,7 @@ public class RepositoryLoggerTest extends RepositoryTestCase {
event.message("message").timestamp(System.currentTimeMillis()).set("residual", true);
repositoryLogger.logHippoEvent(event);
Node logFolder = session.getNode("/hippo:log/default");
Node logFolder = session.getNode("/hippo:log/" + RepositoryLogger.getClusterNodeId(session));
Node currentNode = logFolder;
for (int i = 0; i < 4; i++) {
NodeIterator nodes = currentNode.getNodes();
......
......@@ -21,6 +21,7 @@ import java.sql.SQLException;
import org.junit.Test;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.cms7.services.lock.LockManagerException;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertFalse;
......@@ -152,7 +153,7 @@ public class LockManagerAbortTest extends AbstractLockManagerTest {
boolean locked = false;
try {
locked = lockManager.isLocked(key);
} catch (LockException e1) {
} catch (LockManagerException e1) {
fail(e1.toString());
}
if (!locked) {
......@@ -169,10 +170,13 @@ public class LockManagerAbortTest extends AbstractLockManagerTest {
}
interrupted = true;
lockManager.unlock(key);
try {
lockManager.unlock(key);
} catch (LockException e1) {
fail("After interruption, the current Thread holding the lock should be able to unlock :" + e1.toString());
if (lockManager.isLocked(key)) {
fail("After interruption, the current Thread holding the lock should had been able to unlock");
}
} catch (LockManagerException e1) {
fail("#isLocked test should not fail : " + e.toString());
}
try {
dbRowAssertion(key, "FREE");
......
......@@ -35,10 +35,14 @@ import org.onehippo.cms7.services.HippoServiceRegistry;
import org.onehippo.cms7.services.lock.Lock;
import org.onehippo.cms7.services.lock.LockException;
import org.onehippo.cms7.services.lock.LockManager;
import org.onehippo.cms7.services.lock.LockManagerException;
import org.onehippo.repository.journal.JournalConnectionHelperAccessor;
import org.onehippo.repository.lock.db.DbLockManager;
import org.onehippo.repository.lock.memory.MemoryLockManager;
import org.onehippo.repository.testutils.RepositoryTestCase;
import org.onehippo.repository.lock.InternalLockManager;
import org.onehippo.repository.lock.MutableLock;
import org.onehippo.testutils.log4j.Log4jInterceptor;
import static java.util.concurrent.Executors.newSingleThreadExecutor;
import static org.junit.Assert.assertEquals;
......@@ -112,21 +116,41 @@ public class LockManagerBasicTest extends AbstractLockManagerTest {
assertEquals(0, lockManager.getLocks().size());
}
@Test
public void unlock_non_existing_lock() throws Exception {
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class, DbLockManager.class).build()) {
lockManager.unlock("123");
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Lock '123' does not exist or this cluster node does not contain the lock")));
}
}
@Test
public void other_thread_cannot_unlock_() throws Exception {
final String key = "123";
lockManager.lock(key);
dbRowAssertion(key, "RUNNING");
Thread lockThread = new Thread(() -> {
try {
// unlock should fail with error logging because not owned
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class, DbLockManager.class).build()) {
lockManager.unlock(key);
} catch (LockException e) {
// expected
try {
dbRowAssertion(key, "RUNNING");
} catch (SQLException e1) {
fail(e1.toString());
}
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread '"+Thread.currentThread().getName()+"' should never had invoked #unlock(123)")));
}
// second time again
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class, DbLockManager.class).build()) {
lockManager.unlock(key);
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread '"+Thread.currentThread().getName()+"' should never had invoked #unlock(123)")));
}
try {
assertTrue(lockManager.isLocked(key));
} catch (LockManagerException e) {
fail("#isLocked should not fail : " + e.toString());
}
try {
dbRowAssertion(key, "RUNNING");
} catch (SQLException e1) {
fail(e1.toString());
}
});
......@@ -194,14 +218,22 @@ public class LockManagerBasicTest extends AbstractLockManagerTest {
dbRowAssertion(key, "RUNNING", CLUSTER_NODE_ID, lockThread.getName());
try {
lockManager.unlock(key);
fail("Main thread should not be able to unlock");
} catch (LockException e) {
dbRowAssertion(key, "RUNNING");
// expected
// main thread should not be able to unlock, error log expected
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class, DbLockManager.class).build()) {
lockManager.unlock("123");
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread 'main' should never had invoked #unlock(123)")));
}
// trying again should again result in error log
try (Log4jInterceptor interceptor = Log4jInterceptor.onWarn().trap(MemoryLockManager.class, DbLockManager.class).build()) {
lockManager.unlock("123");
assertTrue(interceptor.messages().anyMatch(m -> m.contains("Thread 'main' should never had invoked #unlock(123)")));
}
assertTrue(lockManager.isLocked(key));
dbRowAssertion(key, "RUNNING");
// expected
runnable.keepAlive = false;
// after the thread is finished, the lock manager should have no locks any more
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment