Cache v2.0 Alpha2: Optimistic Locking + Explicit Versioning

[chasta]

Hi,
I've been trying to use explicit versioning and experiencing some problems .

On certain cases, the OptimisticValidatorInterceptor is throwing exceptions at commit: When calling wrappedNode.isVersioningImplicit(), 'true' is returned even though I can see that my specialized version object has been assigned to the node. That causes an attempt to cast my specialized version to a DefaultDataVersion, failing the transaction... Do you have any idea what could cause this?

My initial suspicions cause me to raise the following two questions...
1) Does explicit locking apply correctly to node operations such as addChild() ?
2) Does it apply correctly to single Cache.put() calls creating more than one level in the tree?

I know that this is not exactly a detailed report; if needed I can try to narrow the case down and give some more details...

[manik]

I presume that by (1) you meant explicit versioning.

The answer is yes, since even when creating a node it could have a version applied to it.

As for (2), the explicit version should only be applied to the final (leaf) node, not the intermediate nodes created. They should receive DefaultDataVersions. See testExplicitVersionOnLeafImplicitParentCreation() in ExplicitVersionsTest

Do you have a stack trace of these exceptions? Also, could you tell me the list of calls in such transactions that fail?

Thanks,
Manik

[chasta]

Yep, I meant explicit versioning, sorry about that...

What seems to happen (at least one case when this has occurred) is that a node gets added, causing an update of its father node. On that point (the put() ) the WorkspaceNode receives the correct version and the 'versioningImplicit' flag is correctly set to false.
However, on commit(), the same node is fetched, and while the version object remains the same (correct) one, the flag is reset to 'true'.

One simple example for a specific operation that causes this is adding a child node using Node.addChild() (to a node which happens to reside two levels under the root node). When working w/o an open transaction (e.g., in auto-transaction per operation mode), this operation fails with the following stack trace:

2007-01-17 09:25:53,579 1728 WARN [org.jboss.cache.interceptors.TxInterceptor] (main:) Commit failed. Clearing stale locks.
2007-01-17 09:25:53,582 1731 ERROR [org.jboss.cache.interceptors.OrderedSynchronizationHandler] (main:) failed calling afterCompletion() on TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:9, tx=org.jboss.cache.transaction.DummyTransaction@27cd63)
java.lang.RuntimeException: Commit failed.
 at org.jboss.cache.interceptors.TxInterceptor.runCommitPhase(TxInterceptor.java:712)
 at org.jboss.cache.interceptors.TxInterceptor$RemoteSynchronizationHandler.afterCompletion(TxInterceptor.java:996)
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.afterCompletion(TxInterceptor.java:1092)
 at org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion(OrderedSynchronizationHandler.java:82)
 at org.jboss.cache.transaction.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
 at org.jboss.cache.transaction.DummyTransaction.commit(DummyTransaction.java:75)
 at org.jboss.cache.transaction.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:78)
 at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:292)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:126)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:151)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:66)
 at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3750)
 at org.jboss.cache.CacheImpl.put(CacheImpl.java:1521)
 at org.jboss.cache.UnversionedNode.addChild(UnversionedNode.java:372)
 at com.mazeppa.yph.tests.CustomVersionTest.phaseIn(CustomVersionTest.java:31)
Caused by: java.lang.ClassCastException: com.mazeppa.yph.tests.CustomVersion cannot be cast to org.jboss.cache.optimistic.DefaultDataVersion
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.commit(OptimisticValidatorInterceptor.java:212)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:68)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:105)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:22)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.TxInterceptor.handleCommitRollback(TxInterceptor.java:655)
 at org.jboss.cache.interceptors.TxInterceptor.runCommitPhase(TxInterceptor.java:698)
 ... 35 more
2007-01-17 09:25:53,588 1737 WARN [org.jboss.cache.interceptors.TxInterceptor] (main:) Commit failed. Clearing stale locks.
2007-01-17 09:25:53,589 1738 ERROR [org.jboss.cache.interceptors.OrderedSynchronizationHandler] (main:) failed calling afterCompletion() on TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:11, tx=org.jboss.cache.transaction.DummyTransaction@4298e)
java.lang.RuntimeException: Commit failed.
 at org.jboss.cache.interceptors.TxInterceptor.runCommitPhase(TxInterceptor.java:712)
 at org.jboss.cache.interceptors.TxInterceptor$RemoteSynchronizationHandler.afterCompletion(TxInterceptor.java:996)
 at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.afterCompletion(TxInterceptor.java:1092)
 at org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion(OrderedSynchronizationHandler.java:82)
 at org.jboss.cache.transaction.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
 at org.jboss.cache.transaction.DummyTransaction.commit(DummyTransaction.java:75)
 at org.jboss.cache.transaction.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:78)
 at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:292)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:126)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:151)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:66)
 at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3750)
 at org.jboss.cache.CacheImpl.put(CacheImpl.java:1521)
 at org.jboss.cache.UnversionedNode.addChild(UnversionedNode.java:372)
 at com.mazeppa.yph.tests.CustomVersionTest.phaseIn(CustomVersionTest.java:31)
Caused by: java.lang.ClassCastException: com.mazeppa.yph.tests.CustomVersion cannot be cast to org.jboss.cache.optimistic.DefaultDataVersion
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.commit(OptimisticValidatorInterceptor.java:212)
 at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:68)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:105)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:22)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
 at org.jboss.cache.interceptors.TxInterceptor.handleCommitRollback(TxInterceptor.java:655)
 at org.jboss.cache.interceptors.TxInterceptor.runCommitPhase(TxInterceptor.java:698)
 ... 35 more

However, we've observed this on other cases as well, cases which involve transactions and are more difficult to reproduce.

[manik]

Could you paste a short unit test method that recreates this? I just tried the following, and didn't see any exceptions (2.0.0 CVS HEAD)

 public void testVersionWithAddNodeImplicitTx() throws Exception
 {
 TestVersion v = new TestVersion("Test");
 Node root = cache.getRoot();
 Fqn f = Fqn.fromString("/a/b");

 cache.getInvocationContext().getOptionOverrides().setDataVersion(v);

 root.addChild(f);

 assertNotNull(cache.get(f));
 assertEquals(v, ((NodeSPI) cache.get(f)).getVersion());


 }

[chasta]

Hmmm. While trying to create a unit test method for you (for the latest version from CVS), I wrote the following method (added to ExplicitVersionsTest):

 Node root = cache.getRoot();

 TestVersion lev2V = new TestVersion("Lev2-v");
 cache.getInvocationContext().getOptionOverrides().setDataVersion(lev2V);
 root.addChild(Fqn.fromString("LEV2"));

 Node lev2 = root.getChild(Fqn.fromString("LEV2"));

 TestVersion lev3V = new TestVersion("Lev3-v");
 cache.getInvocationContext().getOptionOverrides().setDataVersion(lev3V);
 lev2.addChild(Fqn.fromString("LEV3"));

 Node lev3 = lev2.getChild(Fqn.fromString("LEV3"));

 if (lev3 == null)
 throw new Exception("Hay! lev3 is null!");

 TestVersion lev4V = new TestVersion("Lev4-v");
 cache.getInvocationContext().getOptionOverrides().setDataVersion(lev4V);
 lev3.addChild(Fqn.fromString("LEV4"))

The null check for lev3 was added because it is indeed null and the test fails because of that; that seems strange, and was not the behavior I was trying to reproduce...

After commenting out the explicit-versioning related code, everything seemed to work normally; lev3 was not null...

 Node root = cache.getRoot();

// TestVersion lev2V = new TestVersion("Lev2-v");
// cache.getInvocationContext().getOptionOverrides().setDataVersion(lev2V);
 root.addChild(Fqn.fromString("LEV2"));

 Node lev2 = root.getChild(Fqn.fromString("LEV2"));

// TestVersion lev3V = new TestVersion("Lev3-v");
// cache.getInvocationContext().getOptionOverrides().setDataVersion(lev3V);
 lev2.addChild(Fqn.fromString("LEV3"));

 Node lev3 = lev2.getChild(Fqn.fromString("LEV3"));

 if (lev3 == null)
 throw new Exception("Hay! lev3 is null!");

// TestVersion lev4V = new TestVersion("Lev4-v");
// cache.getInvocationContext().getOptionOverrides().setDataVersion(lev4V);
 lev3.addChild(Fqn.fromString("LEV4"))

Am I using the API incorrectly, or is this indeed a bug? I didn't yet manage to reproduce the same bug, but perhaps this is related... I guess in our application some other factor also takes a role in the failure.

[manik]

Ok, I've updated the test in CVS which now reflects this. Looking into it.

[manik]

See JBCACHE-940