[Mulgara-dev] org.mulgara.resolver.spi.LocalizeException: Unable to localize

Thu Jul 3 01:57:20 UTC 2008

Just looking at this trace it appears that the answer (or a sub- 
answer) was closed explicitly, the transaction cleanly terminated,  
and then the answer/sub-answer used again.

An error in this case is expected, and wouldn't be a bug in mulgara  
but a bug in the client. So while I can't guarantee there isn't  
anything screwy going on, there is nothing untoward in this trace.

On 03/07/2008, at 9:49 AM, Pradeep Krishnan wrote:
> 2008-07-02 15:14:40,403 INFO  TransactionalAnswer> Creating Answer:  
> 507856632, xa=0 [RMI TCP Connection(4)-207.7.131.23  
> org.mulgara.resolver.TransactionalAnswer]
> 2008-07-02 15:14:40,403 INFO  TransactionalAnswer> Created Answer:  
> 507856632, xa=1147066451 [RMI TCP Connection(4)-207.7.131.23  
> org.mulgara.resolver.TransactionalAnswer]
> 2008-07-02 15:14:40,403 INFO  TransactionalAnswer> Closing Answer:  
> 507856632, xa=1147066451 [RMI TCP Connection(4)-207.7.131.23  
> org.mulgara.resolver.TransactionalAnswer]
> 2008-07-02 15:14:40,403 INFO  TransactionalAnswer> Closed Answer:  
> 507856632, xa=0 [RMI TCP Connection(4)-207.7.131.23  
> org.mulgara.resolver.TransactionalAnswer]

This here is a clean close, exactly what we would expect to see if  
someone called "answer.close()" at the client.

> 2008-07-02 15:14:40,403 INFO  MulgaraXAResourceContext> Performing  
> commit: :1114926712:-684707558:-475068290: [RMI TCP Connection 
> (5)-207.7.131.23 org.mulgara.resolver.MulgaraXAResourceContext]
> 2008-07-02 15:14:40,403 INFO  MulgaraExternalTransaction> prepare:  
> 1147066451 [RMI TCP Connection(5)-207.7.131.23  
> org.mulgara.resolver.MulgaraExternalTransaction]
> 2008-07-02 15:14:40,404 INFO  MulgaraExternalTransaction> commit:  
> 1147066451 [RMI TCP Connection(5)-207.7.131.23  
> org.mulgara.resolver.MulgaraExternalTransaction]
> 2008-07-02 15:14:40,404 INFO  MulgaraExternalTransaction>  
> cleanupTransaction: 1147066451 [RMI TCP Connection(5)-207.7.131.23  
> org.mulgara.resolver.MulgaraExternalTransaction]

Here we see the transaction terminated cleanly, we know it is clean  
because it did a successful commit() (although, without a write,  
there's almost nothing to do in commit()).  We are using external JTA  
code, so this isn't actually associated with the close above, but was  
triggered by some transaction manager at the client.

One thing that is missing from the trace is the transaction  
initiation, so we don't know if this is a read-only or read-write  
transaction.  Still it hardly matters as everything to this point has  
been both explicit and successful.  Note: This is not a timeout  
issue, as a timeout would trigger a rollback, not a commit.

> 2008-07-02 15:14:40,405 WARN  MulgaraExternalTransaction> Error in  
> answer operation triggered rollback [RMI TCP Connection 
> (4)-207.7.131.23 org.mulgara.resolver.MulgaraExternalTransaction]
> org.mulgara.query.TuplesException: Couldn't evaluate aggregate
> 	at org.mulgara.resolver.SubqueryAnswer.getObject 
> (SubqueryAnswer.java:206)
> 	at org.mulgara.resolver.TransactionalAnswer$1.execute 
> (TransactionalAnswer.java:88)
> 	at org.mulgara.resolver.MulgaraExternalTransaction.execute 
> (MulgaraExternalTransaction.java:155)
> 	at org.mulgara.resolver.TransactionalAnswer.getObject 
> (TransactionalAnswer.java:86)
> 	at org.mulgara.server.rmi.AnswerPageImpl.<init> 
> (AnswerPageImpl.java:113)
> 	at org.mulgara.server.rmi.AnswerPageImpl.<init> 
> (AnswerPageImpl.java:143)
> 	at org.mulgara.server.rmi.AnswerWrapperRemoteAnswer.nextPage 
> (AnswerWrapperRemoteAnswer.java:240)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke 
> (NativeMethodAccessorImpl.java:39)
> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke 
> (DelegatingMethodAccessorImpl.java:25)
> 	at java.lang.reflect.Method.invoke(Method.java:585)
> 	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java: 
> 294)
> 	at sun.rmi.transport.Transport$1.run(Transport.java:153)
> 	at java.security.AccessController.doPrivileged(Native Method)
> 	at sun.rmi.transport.Transport.serviceCall(Transport.java:149)
> 	at sun.rmi.transport.tcp.TCPTransport.handleMessages 
> (TCPTransport.java:466)
> 	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run 
> (TCPTransport.java:707)
> 	at java.lang.Thread.run(Thread.java:595)

Note this line:
> 	at org.mulgara.server.rmi.AnswerWrapperRemoteAnswer.nextPage 
> (AnswerWrapperRemoteAnswer.java:240)

If there is a problem at our end, it will almost certainly be related  
to the interaction between answer-paging and the transaction system.   
We are in nextPage(), and so if everything is fine at the client this  
is probably where we start looking.  Of course, someone has to first  
explain why we have a nice clean and explicit close() call  
immediately before this :).

<SNIP> The next bit of the trace is irrelevant, just unrolling the  
stack. Then we get to the localize that failed:

> Caused by: org.mulgara.resolver.spi.LocalizeException: Unable to  
> localize http://purl.org/dc/terms/hasPart - Attempting to localize  
> outside transaction (STATE = 4) 569080239
> 	at org.mulgara.resolver.StringPoolSession.localize 
> (StringPoolSession.java:396)
> 	at org.mulgara.resolver.StringPoolSession.localize 
> (StringPoolSession.java:196)
> 	at org.mulgara.resolver.store.StatementStoreResolver.localize 
> (StatementStoreResolver.java:446)
> 	at org.mulgara.resolver.LocalQueryResolver.localize 
> (LocalQueryResolver.java:129)
> 	at org.mulgara.resolver.DefaultConstraintHandlers$29.localize 
> (DefaultConstraintHandlers.java:394)
> 	at org.mulgara.resolver.ConstraintOperations.localize 
> (ConstraintOperations.java:240)
> 	at org.mulgara.resolver.LocalQueryResolver.resolve 
> (LocalQueryResolver.java:178)
> 	... 28 more

Note the STATE = 4, (this code hasn't been updated since Java 1.4,  
hence the lack of enums). Anything other than 0 indicates a  
transaction that is either uninitialized, terminated, or in the  
process of being terminated. 4 indicates RELEASE, ie. transaction has  
been terminated and cleaned up, and the phase released.  Hence the  
exception when we try to use it.

So we come back to.... why have we closed the answer, and why did the  
transaction-manager end the transaction, if we are still wanting to  
use the answer?

Andrae