NPE caught in handleClientEvent in latest cvs-version

Arjen van der Meijden <[email protected]> Sat, 21 Aug 2004 13:14:20 +0200
Newsgroups gmane.comp.java.ozone.user
Message-ID <[email protected]>
Hi list,

I've replaced my running ozone 1.2 with a cvs-version, just to see how 
much performance-improvements and such it would jield. But I can't get 
the code, that was running perfectly using 1.2, to run on the cvs-version.

The failing code is basically:
OzoneMap map = (OzoneMap)db.objectForName("map_name");
  // completes, map is a previously created NodeTreeMap and it's proxy 
is returned to the client

Object x = map.get(someKey);
  // does not complete, the clientside simply stalls, while the server 
is catching an NPE

The above (extracted) code jields a serverside NPE in handleClientEvent, 
according to the logging-output in the ozone-console/log. I've set it to 
log at the FINEST-level and attached the log of those two calls.

Here is the last line of the log-output:
WARNING [org.ozoneDB.core.InvokeServer.handleClientEvent] 
handleClientEvent(): org.ozoneDB.UnexpectedException: 
java.lang.NullPointerException

In the attached log, the get-command is issued with an Integer with the 
value 1690. The return-value of that get-command at the NodeTreeMap is 
null, by the way, I certainly hope that isn't causing this NPE over 
there... I've not tested anything else yet, this was simply cleaning up 
the database (ozoneInst) and starting the application again. All classes 
have been recompiled (and run through opp), the JVM is jdk 1.5.0-beta2 
but the Ozone-1.2 was also run in 1.5 (not compiled though).

Best regards,

Arjen van der Meijden
ozone-log.txt (text/plain, 8.2 KB)
FINE [org.ozoneDB.core.InvokeServer.newClient] connection established...
FINE [org.ozoneDB.core.InvokeServer.handleClientEvent] user logged in: tomcat
FINE [org.ozoneDB.core.TransactionManager.handleCommand] handleCommand(): [org.ozoneDB.core.DbRemote.DbObjForName]
FINEST [org.ozoneDB.core.TransactionManager.completeTransaction] completeTransaction(): [org.ozoneDB.core.DbRemote.DbObjForName]
FINEST [org.ozoneDB.core.TransactionManager.newTransaction] newTransaction() OzoneUser: tomcat
FINER [org.ozoneDB.core.TransactionManager.newTransaction] newTransaction(): ta=ta[id=5168,blocker=null], thread=Thread[Thread-13,5,org.ozoneDB.core.InvokeServer]
FINEST [org.ozoneDB.core.TransactionManager.performCommand] performCommand(): start: ta[id=5168,blocker=null], [org.ozoneDB.core.DbRemote.DbObjForName]
FINE [org.ozoneDB.core.Transaction.performCommand] performCommand(): ta[id=5168,blocker=null], [org.ozoneDB.core.DbRemote.DbObjForName]
FINEST [org.ozoneDB.core.Transaction.objectForName] objectForName() userIDMap
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINEST [org.ozoneDB.core.TransactionManager.performCommand] performCommand(): end: ta[id=5168,blocker=null], [org.ozoneDB.core.DbRemote.DbObjForName]
FINEST [org.ozoneDB.core.TransactionManager.prepareTransaction] prepareTransaction()
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.prepareCommit] prepareCommitTransaction()
FINEST [org.ozoneDB.core.TransactionManager.commitTransaction] commitTransaction() ta[id=5168,blocker=null] [org.ozoneDB.core.DbRemote.DbObjForName]
FINEST [org.ozoneDB.core.TransactionManager.beginExclusion] beginExclusion()
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit] commitTransaction()
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit]     idTable.count(): 0
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit]     nameTable.count(): 0
FINEST [org.ozoneDB.core.TransactionManager.endExclusion] endExclusion()
FINEST [org.ozoneDB.core.TransactionManager.notifyWaitingTransactions] notifyWaitingTransactions()
FINEST [org.ozoneDB.core.TransactionManager.deleteTransaction] deleteTransaction()
FINER [org.ozoneDB.core.TransactionManager.deleteTransaction] deleteTransaction() ta=ta[id=5168,blocker=null]
FINER [org.ozoneDB.core.InvokeServer.handleClientEvent] sending back result = class org.ozoneDB.collections.NodeTreeMapImpl_Proxy remoteID:5106 for object [org.ozoneDB.core.DbRemote.DbObjForName]
FINE [org.ozoneDB.core.TransactionManager.handleCommand] handleCommand(): [DbInvoke: 25]
FINEST [org.ozoneDB.core.TransactionManager.completeTransaction] completeTransaction(): [DbInvoke: 25]
FINEST [org.ozoneDB.core.TransactionManager.newTransaction] newTransaction() OzoneUser: tomcat
FINER [org.ozoneDB.core.TransactionManager.newTransaction] newTransaction(): ta=ta[id=5169,blocker=null], thread=Thread[Thread-13,5,org.ozoneDB.core.InvokeServer]
FINEST [org.ozoneDB.core.TransactionManager.performCommand] performCommand(): start: ta[id=5169,blocker=null], [DbInvoke: 25]
FINE [org.ozoneDB.core.Transaction.performCommand] performCommand(): ta[id=5169,blocker=null], [DbInvoke: 25]
FINER [org.ozoneDB.core.DbRemote.DbInvoke.perform] DbInvoke.perform(): start
FINEST [org.ozoneDB.core.Transaction.invokeObject] invokeObject(,25): start
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINER [org.ozoneDB.core.Transaction.acquireContainer] ta[id=5169,blocker=5106].acquireContainer(5106): successful.
FINEST [org.ozoneDB.core.storage.wizardStore.WizardStore.updateLockLevel] updateLockLevel()
FINER [org.ozoneDB.core.storage.wizardStore.WizardCluster.updateLockLevel] updateLockLevel(): 5107
FINER [org.ozoneDB.core.storage.wizardStore.WizardCluster.updateLockLevel]         lock: 1
FINEST [org.ozoneDB.core.AbstractObjectContainer.invokeTarget] invoke(): calling method get with arguments [1690]
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINER [org.ozoneDB.core.Transaction.acquireContainer] ta[id=5169,blocker=5115].acquireContainer(5115): successful.
FINEST [org.ozoneDB.core.storage.wizardStore.WizardStore.updateLockLevel] updateLockLevel()
FINER [org.ozoneDB.core.storage.wizardStore.WizardCluster.updateLockLevel] updateLockLevel(): 5111
FINER [org.ozoneDB.core.storage.wizardStore.WizardCluster.updateLockLevel]         lock: 1
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINER [org.ozoneDB.core.Transaction.acquireContainer] ta[id=5169,blocker=5115].acquireContainer(5115): successful.
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINER [org.ozoneDB.core.Transaction.acquireContainer] ta[id=5169,blocker=5115].acquireContainer(5115): successful.
FINEST [org.ozoneDB.core.Transaction.invokeObject] invokeObject(,25): end
FINER [org.ozoneDB.core.DbRemote.DbInvoke.perform] DbInvoke.perform(): end
FINEST [org.ozoneDB.core.TransactionManager.performCommand] performCommand(): end: ta[id=5169,blocker=null], [DbInvoke: 25]
FINEST [org.ozoneDB.core.TransactionManager.prepareTransaction] prepareTransaction()
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.prepareCommit] prepareCommitTransaction()
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.prepareCommit] checking cluster: 5111 ...
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.prepareCommitCluster] prepareCommitCluster(): 5111
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINEST [org.ozoneDB.core.storage.wizardStore.WizardCluster.prepareCommit] prepareCommit()5111
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.prepareCommit] checking cluster: 5107 ...
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.prepareCommitCluster] prepareCommitCluster(): 5107
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINEST [org.ozoneDB.core.storage.wizardStore.WizardCluster.prepareCommit] prepareCommit()5107
FINEST [org.ozoneDB.core.TransactionManager.commitTransaction] commitTransaction() ta[id=5169,blocker=null] [DbInvoke: 25]
FINEST [org.ozoneDB.core.TransactionManager.beginExclusion] beginExclusion()
FINEST [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit] commitTransaction()
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit] commit cluster: 5111
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.commitCluster] commitCluster(): 5111
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5111]
FINEST [org.ozoneDB.core.storage.wizardStore.WizardCluster.commit] commit()5111
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit] commit cluster: 5107
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.commitCluster] commitCluster(): 5107
FINEST [org.ozoneDB.core.storage.wizardStore.ClusterStore.loadCluster] returning WizardCluster: WizardCluster[id=5107]
FINEST [org.ozoneDB.core.storage.wizardStore.WizardCluster.commit] commit()5107
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit]     idTable.count(): 2
FINER [org.ozoneDB.core.storage.wizardStore.WizardTransaction.commit]     nameTable.count(): 0
FINEST [org.ozoneDB.core.TransactionManager.endExclusion] endExclusion()
FINEST [org.ozoneDB.core.TransactionManager.notifyWaitingTransactions] notifyWaitingTransactions()
FINEST [org.ozoneDB.core.TransactionManager.deleteTransaction] deleteTransaction()
FINER [org.ozoneDB.core.TransactionManager.deleteTransaction] deleteTransaction() ta=ta[id=5169,blocker=null]
WARNING [org.ozoneDB.core.InvokeServer.handleClientEvent] handleClientEvent(): org.ozoneDB.UnexpectedException: java.lang.NullPointerException