[Bugfix] fixed not unlocked objects after TX

When a TX is closed, all locked objects are unlocked. The but originated from multiple commands being performed for the same object, thus the object was locked multiple times i.e. the lock counter was >1. Now added a releaseLock() method which is called by the TX when the TX is closed so that the lock counter is really 0 and the lock is released.

- Added tests for this situation
- documented the LockHandler

ch.eitchnet.utils

@@ -1 +1 @@
-Subproject commit a67df72f3f9b795796896889c2dbe1cf8561ccd2
+Subproject commit cde6eb652ec2c12ce22c8cb21a16589d56f8a49f

li.strolch.agent/src/main/java/li/strolch/agent/api/LockHandler.java

@@ -15,14 +15,67 @@
  */
 package li.strolch.agent.api;
 
+import java.util.concurrent.locks.Lock;
+
+import li.strolch.agent.impl.DefaultLockHandler;
+import li.strolch.model.Locator;
 import li.strolch.model.StrolchRootElement;
 
 /**
+ * <p>
+ * In Strolch locking of objects is done by keeping a lock for every {@link StrolchRootElement} by using the
+ * {@link Locator} to find the lock. Instead of adding a lock to the model, the lock is stored by the
+ * {@link LockHandler}.
+ * </p>
+ * 
+ * <p>
+ * Since new {@link StrolchRootElement} might not be known by the {@link ElementMap ElementMaps} but you still want to
+ * lock an object globally, then locking on the {@link Locator} solves this, as the locator is an immutable object and
+ * can easily be created before the actual object exists
+ * </p>
+ * 
+ * <p>
+ * See concrete implementations for which concrete locking implementation is used
+ * </p>
+ * 
+ * @see DefaultLockHandler
+ * 
  * @author Robert von Burg <eitch@eitchnet.ch>
  */
 public interface LockHandler {
 
+	/**
+	 * Locks the given element by using the element's {@link Locator} and creating a lock on it. Calling lock multiple
+	 * times from the same thread will not lock, it is up to the concrete implementation to define if a lock counter is
+	 * used
+	 * 
+	 * @param element
+	 *            the element for which a {@link Lock} on its {@link Locator} is to be created and/or locked
+	 */
 	public void lock(StrolchRootElement element);
 
+	/**
+	 * <p>
+	 * Unlocks the given element by finding the element's lock by its {@link Locator}. It is up to the concrete
+	 * implementation to define if unlocking an unlocked element will fail or not. This method might not completely
+	 * unlock the element if a lock counter is used and the object was locked multiple times.
+	 * </p>
+	 * 
+	 * <p>
+	 * If the lock must be completely released, then use {@link #releaseLock(StrolchRootElement)}
+	 * </p>
+	 * 
+	 * @param element
+	 *            the element for which the current/last {@link Lock} is to be unlocked
+	 */
 	public void unlock(StrolchRootElement element);
+
+	/**
+	 * Releases the lock on the given element, by unlocking all locks, i.e. after this method is called, no lock will be
+	 * held anymore by the current thread
+	 * 
+	 * @param element
+	 *            the element for which the {@link Lock} on the {@link Locator} is to be released
+	 */
+	public void releaseLock(StrolchRootElement element);
 }

li.strolch.agent/src/main/java/li/strolch/agent/api/StrolchRealm.java

@@ -31,6 +31,8 @@ public interface StrolchRealm {
 
 	public void unlock(StrolchRootElement lockedElement);
 
+	public void releaseLock(StrolchRootElement lockedElement);
+
 	public DataStoreMode getMode();
 
 	public StrolchTransaction openTx(Certificate certificate, Class<?> clazz);

li.strolch.agent/src/main/java/li/strolch/agent/impl/DefaultLockHandler.java

@@ -68,7 +68,7 @@ public class DefaultLockHandler implements LockHandler {
 			this.lockMap.put(locator, lock);
 		}
 
-		lock(this.tryLockTimeUnit, this.tryLockTime, lock);
+		lock(this.tryLockTimeUnit, this.tryLockTime, lock, element);
 	}
 
 	@Override
@@ -82,15 +82,26 @@ public class DefaultLockHandler implements LockHandler {
 		}
 	}
 
+	@Override
+	public void releaseLock(StrolchRootElement element) {
+		Locator locator = element.getLocator();
+		ReentrantLock lock = this.lockMap.get(locator);
+		if (lock == null || !lock.isHeldByCurrentThread()) {
+			logger.error(MessageFormat.format("Trying to unlock not locked element {0}", locator)); //$NON-NLS-1$
+		} else {
+			releaseLock(lock);
+		}
+	}
+
 	/**
 	 * @see java.util.concurrent.locks.ReentrantLock#tryLock(long, TimeUnit)
 	 */
-	private void lock(TimeUnit timeUnit, long tryLockTime, ReentrantLock lock) {
+	private void lock(TimeUnit timeUnit, long tryLockTime, ReentrantLock lock, StrolchRootElement element) {
 		try {
 
 			if (!lock.tryLock(tryLockTime, timeUnit)) {
 				String msg = "Failed to acquire lock after {0}s for {1}"; //$NON-NLS-1$
-				msg = MessageFormat.format(msg, timeUnit.toSeconds(tryLockTime), toString());
+				msg = MessageFormat.format(msg, timeUnit.toSeconds(tryLockTime), element.getLocator());
 				throw new StrolchException(msg);
 			}
 			if (logger.isDebugEnabled())
@@ -108,4 +119,13 @@ public class DefaultLockHandler implements LockHandler {
 		if (logger.isDebugEnabled())
 			logger.debug("unlocking " + toString()); //$NON-NLS-1$
 	}
+
+	/**
+	 * @see java.util.concurrent.locks.ReentrantLock#unlock()
+	 */
+	private void releaseLock(ReentrantLock lock) {
+		while (lock.isHeldByCurrentThread() && lock.isLocked()) {
+			unlock(lock);
+		}
+	}
 }

li.strolch.agent/src/main/java/li/strolch/agent/impl/InternalStrolchRealm.java

@@ -77,13 +77,17 @@ public abstract class InternalStrolchRealm implements StrolchRealm {
 		this.lockHandler.unlock(lockedElement);
 	}
 
+	@Override
+	public void releaseLock(StrolchRootElement lockedElement) {
+		this.lockHandler.releaseLock(lockedElement);
+	}
+
 	public void initialize(ComponentContainer container, ComponentConfiguration configuration) {
 
 		String propTryLockTimeUnit = StrolchConstants.makeRealmKey(this.realm, PROP_TRY_LOCK_TIME_UNIT);
 		String propTryLockTime = StrolchConstants.makeRealmKey(this.realm, PROP_TRY_LOCK_TIME);
 
-		String enableAuditKey = StrolchConstants.makeRealmKey(getRealm(),
-				DefaultRealmHandler.PROP_ENABLE_AUDIT_TRAIL);
+		String enableAuditKey = StrolchConstants.makeRealmKey(getRealm(), DefaultRealmHandler.PROP_ENABLE_AUDIT_TRAIL);
 		this.auditTrailEnabled = configuration.getBoolean(enableAuditKey, Boolean.FALSE);
 
 		String enableAuditForReadKey = StrolchConstants.makeRealmKey(getRealm(),

li.strolch.agent/src/main/java/li/strolch/persistence/api/AbstractTransaction.java

@@ -199,9 +199,9 @@ public abstract class AbstractTransaction implements StrolchTransaction {
 		this.lockedElements.remove(element);
 	}
 
-	private void unlockElements() {
+	private void releaseElementLocks() {
 		for (StrolchRootElement lockedElement : this.lockedElements) {
-			this.realm.unlock(lockedElement);
+			this.realm.releaseLock(lockedElement);
 		}
 	}
 
@@ -472,7 +472,7 @@ public abstract class AbstractTransaction implements StrolchTransaction {
 			throw new StrolchPersistenceException(msg, e);
 
 		} finally {
-			unlockElements();
+			releaseElementLocks();
 		}
 	}
 
@@ -487,7 +487,7 @@ public abstract class AbstractTransaction implements StrolchTransaction {
 		} catch (Exception e) {
 			handleFailure(start, e);
 		} finally {
-			unlockElements();
+			releaseElementLocks();
 		}
 	}
 
@@ -510,19 +510,23 @@ public abstract class AbstractTransaction implements StrolchTransaction {
 		StringBuilder sb = new StringBuilder();
 		sb.append("TX user=");
 		sb.append(this.certificate.getUsername());
+		sb.append(", action=");
+		sb.append(this.action);
 		sb.append(", realm="); //$NON-NLS-1$
 		sb.append(getRealmName());
 		sb.append(", took="); //$NON-NLS-1$
 		sb.append(StringHelper.formatNanoDuration(txDuration));
-		sb.append(", close="); //$NON-NLS-1$
-		sb.append(StringHelper.formatNanoDuration(closeDuration));
-		
-		if (isAuditTrailEnabled()) {
+		if (closeDuration >= 100000000L) {
+			sb.append(", close="); //$NON-NLS-1$
+			sb.append(StringHelper.formatNanoDuration(closeDuration));
+		}
+
+		if (isAuditTrailEnabled() && auditTrailDuration >= 100000000L) {
 			sb.append(", auditTrail="); //$NON-NLS-1$
 			sb.append(StringHelper.formatNanoDuration(auditTrailDuration));
 		}
-		
-		if (isObserverUpdatesEnabled()) {
+
+		if (isObserverUpdatesEnabled() && observerUpdateDuration >= 100000000L) {
 			sb.append(", updates="); //$NON-NLS-1$
 			sb.append(StringHelper.formatNanoDuration(observerUpdateDuration));
 		}

li.strolch.rest/src/main/java/li/strolch/rest/DefaultStrolchSessionHandler.java

@@ -65,7 +65,7 @@ public class DefaultStrolchSessionHandler extends StrolchComponent implements St
 		this.privilegeHandler = getContainer().getComponent(PrivilegeHandler.class);
 		this.certificateMap = new HashMap<>();
 
-		this.sessionTimeoutTimer = new Timer("SessionTimeoutTimer"); //$NON-NLS-1$
+		this.sessionTimeoutTimer = new Timer("SessionTimeoutTimer", true); //$NON-NLS-1$
 		long checkInterval = TimeUnit.MINUTES.toMillis(1);
 		this.sessionTimeoutTimer.schedule(new SessionTimeoutTask(), checkInterval, checkInterval);
 

li.strolch.rest/src/main/java/li/strolch/rest/RestfulStrolchComponent.java

@@ -132,8 +132,8 @@ public class RestfulStrolchComponent extends StrolchComponent {
 		}
 
 		// restful logging and tracing
-		this.restLogging = configuration.getBoolean(PARAM_REST_LOGGING, false);
-		this.restLoggingEntity = configuration.getBoolean(PARAM_REST_LOGGING_ENTITY, false);
+		this.restLogging = configuration.getBoolean(PARAM_REST_LOGGING, Boolean.FALSE);
+		this.restLoggingEntity = configuration.getBoolean(PARAM_REST_LOGGING_ENTITY, Boolean.FALSE);
 		this.restTracing = configuration.getString(PARAM_REST_TRACING, "OFF"); //$NON-NLS-1$
 		this.restTracingThreshold = configuration.getString(PARAM_REST_TRACING_THRESHOLD, "TRACE"); //$NON-NLS-1$
 

li.strolch.rest/src/main/java/li/strolch/rest/endpoint/AuthenticationService.java

@@ -121,33 +121,32 @@ public class AuthenticationService {
 	@DELETE
 	@Consumes(MediaType.APPLICATION_JSON)
 	@Produces(MediaType.APPLICATION_JSON)
-	@Path("{authToken}")
-	public Response logout(@PathParam("authToken") String authToken) {
+	@Path("{sessionId}")
+	public Response logout(@PathParam("sessionId") String sessionId) {
 
 		LogoutResult logoutResult = new LogoutResult();
 
-		GenericEntity<LogoutResult> entity = new GenericEntity<LogoutResult>(logoutResult, LogoutResult.class) {
-			//
-		};
 		try {
 
 			StrolchSessionHandler sessionHandlerHandler = RestfulStrolchComponent.getInstance().getComponent(
 					StrolchSessionHandler.class);
-			Certificate certificate = sessionHandlerHandler.validate(authToken);
+			Certificate certificate = sessionHandlerHandler.validate(sessionId);
 			sessionHandlerHandler.invalidateSession(certificate);
 
+			logoutResult.setUsername(certificate.getUsername());
+			logoutResult.setSessionId(sessionId);
 			logoutResult.setMsg(MessageFormat.format("{0} has been logged out.", certificate.getUsername())); //$NON-NLS-1$
-			return Response.ok().entity(entity).build();
+			return Response.ok().entity(logoutResult).build();
 
 		} catch (StrolchException | PrivilegeException e) {
 			logger.error(e.getMessage(), e);
 			logoutResult.setMsg(MessageFormat.format("Could not logout due to: {0}", e.getMessage())); //$NON-NLS-1$
-			return Response.status(Status.UNAUTHORIZED).entity(entity).build();
+			return Response.status(Status.UNAUTHORIZED).entity(logoutResult).build();
 		} catch (Exception e) {
 			logger.error(e.getMessage(), e);
 			String msg = e.getMessage();
 			logoutResult.setMsg(MessageFormat.format("{0}: {1}", e.getClass().getName(), msg)); //$NON-NLS-1$
-			return Response.serverError().entity(entity).build();
+			return Response.serverError().entity(logoutResult).build();
 		}
 	}
 }

li.strolch.service/src/test/java/li/strolch/service/test/LockingTest.java

@@ -96,6 +96,13 @@ public class LockingTest {
 			runners.add(new LockingRunner(svc, arg));
 		}
 
+		runRunners(runners);
+
+		// now assert that we can perform another such service, thus validating that the resource is not locked any longer
+		doLockServiceTest(false);
+	}
+
+	private void runRunners(List<LockingRunner> runners) throws InterruptedException {
 		this.run = false;
 		for (LockingRunner lockingRunner : runners) {
 			lockingRunner.start();
@@ -112,11 +119,30 @@ public class LockingTest {
 			assertEquals(ServiceResultState.FAILED, result.getState());
 			assertThat(result.getMessage(), containsString("Failed to acquire lock after"));
 		}
+	}
+
+	@Test
+	public void shouldUnlockCompletelyOnMultipleLock() throws InterruptedException {
+
+		List<LockingRunner> runners = new ArrayList<>();
 
-		// now assert that we can perform another such service, thus validating that the resource is not locked any longer
 		LockingServiceTest svc = new LockingServiceTest();
 		LockingArgumentTest arg = new LockingArgumentTest();
 		arg.longRunning = false;
+		arg.nrOfLocks = 5;
+		arg.resourceLoc = Locator.valueOf(RESOURCE_LOCATOR);
+		runners.add(new LockingRunner(svc, arg));
+
+		runRunners(runners);
+
+		// now assert that we can perform another such service, thus validating that the resource is not locked any longer
+		doLockServiceTest(false);
+	}
+
+	private void doLockServiceTest(boolean longRunning) {
+		LockingServiceTest svc = new LockingServiceTest();
+		LockingArgumentTest arg = new LockingArgumentTest();
+		arg.longRunning = longRunning;
 		arg.resourceLoc = Locator.valueOf(RESOURCE_LOCATOR);
 		ServiceResult result = getServiceHandler().doService(login(), svc, arg);
 		assertEquals(ServiceResultState.SUCCESS, result.getState());
@@ -157,6 +183,7 @@ public class LockingTest {
 	private static class LockingArgumentTest extends ServiceArgument {
 		private static final long serialVersionUID = 1L;
 		public boolean longRunning;
+		public int nrOfLocks = 1;
 		public Locator resourceLoc;
 	}
 
@@ -177,7 +204,8 @@ public class LockingTest {
 					Thread.sleep(200l);
 
 				Resource res = tx.findElement(arg.resourceLoc);
-				tx.lock(res);
+				for (int i = 0; i < arg.nrOfLocks; i++)
+					tx.lock(res);
 
 				if (arg.longRunning)
 					Thread.sleep(5000l);