IllegalArgumentException: transaction closed ?

Alex

unread,

Jul 22, 2012, 8:54:00 AM7/22/12

to objectify...@googlegroups.com

So I was stress-testing parts of my app, to see how it'd handle many requests in a short
period of time, and a very unusual exception was thrown:
java.lang.IllegalArgumentException: transaction closed
I'm not sure if this is an Objectify or a AppEngine issue (I suspect the latter), but figured I'd
ask in case Objectify does anything weird with the transactions that I wasn't aware of.

Basically, the client would send in an RPC request, which would begin a transaction.
This transaction loaded a polymorphic parent object with a load group, to also load its
list of children (also polymorphic if it matters - also, neither have @Cache... though for
memory that's turned on by default in ofy 4?), grabs a child and calls some process method.
Inside the process method, a task is queued if a flag is not set (and then sets the flag).
Whether or not this flag is set, a result object for the user is returned by the process method.

However outside of the transaction, I throw an exception, and on the client side, I have it
reattempting the request upon failure. Usually the reattempts are exponentially delayed and
then cut off, but for the purposes of the test, I disabled this and it essentially just spams
real quick and then gives up.

I noticed that if I do save.now() this error goes away. So I assume this has something weird
to do with saving asynchronously, and though I understand you can get some "stale" reads
between the asynchronous write phases, I was under the impression that when performing
another transaction on a root entity (I say parent/child, but there is no @Parent, just a key/ref
and a parent/child "relationship"), it wont finalise the transaction until any previous writes
have been completed...
Also, yea, this test is quite contrived, and usually there'd be some user latency etc. involved,
but ignoring that - how can multiple tasks be enqueued with a single flag inside a transaction?
And what on earth is that exception from? lol
(the multiple task enqueuement occurs with both synchronous and asynchronous saving)

Here is my RPC function:
public Result requestResult(..., final long requestId, ...)
{
    // auth checking omitted

    Result result = ofy().transact(new Work<Result>()
    {
        @Override
        public Result run()
        {
            Parent parent = ofy().load().group(Parent.WithTables.class).type(ParentBase.class).id(requestId).get();
            Child child = parent.requestOpenChild();

            Result r = child.processRequest(...); // flag set in here and task enqueued (so task cannot be enqueued twice... so I thought)

            ofy().save().entity(child); // tried saving as both async and sync
            ofy().save().entity(parent);

            return r;
        }
    });

    throw new IllegalStateException("test"); // results in client firing another requestResult
    // return result
}

Somewhere within the process function there is:
if (state != State.WAITING) return new Result(...);

state = State.PHASE1;

Queue queue = QueueFactory.getDefaultQueue();
queue.add(withUrl("/process").
        param("c", Long.toString(childId)).
        ...
        countdownMillis(Child.PROCESS_DELAY_SEC * 1000));

return new Result(...);

The log output:
SEVERE: Exception in ProcessServlet.doPost(); c = xxx, ...
java.lang.IllegalArgumentException: transaction closed
    at com.google.appengine.api.datastore.DatastoreApiHelper.translateError(DatastoreApiHelper.java:36)
    at com.google.appengine.api.datastore.DatastoreApiHelper$1.convertException(DatastoreApiHelper.java:76)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:106)
    at com.google.appengine.api.datastore.FutureHelper$CumulativeAggregateFuture.get(FutureHelper.java:145)
    at com.google.appengine.api.datastore.FutureHelper$TxnAwareFuture.get(FutureHelper.java:222)
    at com.googlecode.objectify.cache.TriggerFuture.get(TriggerFuture.java:102)
    at com.googlecode.objectify.impl.ResultAdapter.now(ResultAdapter.java:29)
    at com.googlecode.objectify.util.ResultWrapper.translate(ResultWrapper.java:20)
    at com.googlecode.objectify.util.ResultWrapper.translate(ResultWrapper.java:1)
    at com.googlecode.objectify.util.ResultTranslator.nowUncached(ResultTranslator.java:21)
    at com.googlecode.objectify.util.ResultCache.now(ResultCache.java:27)
    at com.googlecode.objectify.impl.cmd.ObjectifyImplTxn$TransactionImpl.commitAsync(ObjectifyImplTxn.java:60)
    at com.googlecode.objectify.impl.cmd.ObjectifyImplTxn$TransactionImpl.commit(ObjectifyImplTxn.java:53)
    at com.googlecode.objectify.impl.cmd.ObjectifyImpl.transactOnce(ObjectifyImpl.java:256)
    at com.googlecode.objectify.impl.cmd.ObjectifyImpl.transactNew(ObjectifyImpl.java:232)
    at com.googlecode.objectify.impl.cmd.ObjectifyImpl.transactNew(ObjectifyImpl.java:222)
    at com.googlecode.objectify.impl.cmd.ObjectifyImpl.transact(ObjectifyImpl.java:214)
    at com.googlecode.objectify.util.cmd.ObjectifyWrapper.transact(ObjectifyWrapper.java:165)
    at com.qwerty.server.servlet.ProcessServlet.doPost(ProcessServlet.java:46)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263)
    at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178)
    at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)
    at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62)
    at com.googlecode.objectify.cache.AsyncCacheFilter.doFilter(AsyncCacheFilter.java:59)
    at com.googlecode.objectify.ObjectifyFilter.doFilter(ObjectifyFilter.java:49)
    at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163)
    at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
    at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118)
    at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.appengine.tools.development.HeaderVerificationFilter.doFilter(HeaderVerificationFilter.java:35)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.appengine.api.blobstore.dev.ServeBlobFilter.doFilter(ServeBlobFilter.java:60)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.appengine.tools.development.StaticFileFilter.doFilter(StaticFileFilter.java:125)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.appengine.tools.development.BackendServersFilter.doFilter(BackendServersFilter.java:97)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
    at com.google.appengine.tools.development.DevAppEngineWebAppContext.handle(DevAppEngineWebAppContext.java:94)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at com.google.appengine.tools.development.JettyContainerService$ApiProxyHandler.handle(JettyContainerService.java:370)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
    at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:938)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:755)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)

Jeff Schnitzer

unread,

Jul 22, 2012, 1:04:09 PM7/22/12

to objectify...@googlegroups.com

Try changing this:

Queue queue = QueueFactory.getDefaultQueue();
queue.add(withUrl("/process")...

...to this...

Queue queue = QueueFactory.getDefaultQueue();
queue.add(ofy().getTxn(), withUrl("/process")...

...and let me know if that fixes the problem. The transactionless
add() method uses GAE's builtin thread local transactions, which
Objectify doesn't use (it's a problem for our transaction-aware cache
or the ability to interleave transactions and transactionless
operations). It should still work anyways... but it looks suspicious.

Also, are you putting that delay in place because otherwise the task
begins right away and conflicts with the original transaction? With a
properly transactionally enqueued task, that isn't an issue - the task
is only activated after the txn commits.

Another thing to try (even if the extra txn parameter to add() works) is call:

ofy().cache(false).transact(...

This will give me a better idea where the problem is.

Question: Do you make any other calls to DatastoreService (the raw
api) anywhere?

Jeff

Alex

unread,

Jul 26, 2012, 12:58:53 AM7/26/12

to objectify...@googlegroups.com, je...@infohazard.org

Sorry for the belated response - fun-fun life stuff etc. lol

Anyway, not long after I posted this, I started modifying the parent-child
dependencies to remove the need to load the parent for the task queue
processing. So unfortunately (?) I can not for the life of me reproduce
that weird exception any more. I even tried rolling back just to
"get an answer", but it didn't seem to want to happen.
A good thing I guess?.

With regards to the task enqueuement - I ran a couple of tests without
specifying the queue transaction, and it appeared to have no problems
(the task wasn't enqueued unless transaction committed). Though to be
on the safe side, I've changed them all to use the local Objectify
transaction context.

For the multiple-enqueuement issue - I think I noticed a set of race
conditions in processRequest, and since the fix/changes I made, this
no longer happens (the code/RPC was all dev. code at the time; and
wasn't in production use).

And as for you question - nope. That's what I have Objectify for. :)

Also, I tried the cache(false), but since I couldn't get the exception
to fire even without it, it's a bit of a moot point.

My guess is that I was unrealistically thrashing the datastore and just
encountered some weird rare state. A google search brought up very
little about the exception, so it wouldn't surprise me if it's a DevMode
thing that I'll never see again... Here's hoping!

Alex.

On Monday, 23 July 2012 02:34:09 UTC+9:30, Jeff Schnitzer wrote:

Try changing this:

Queue queue = QueueFactory.getDefaultQueue();
queue.add(withUrl("/process")...

...to this...

Queue queue = QueueFactory.getDefaultQueue();
queue.add(ofy().getTxn(), withUrl("/process")...

...and let me know if that fixes the problem. The transactionless
add() method uses GAE's builtin thread local transactions, which
Objectify doesn't use (it's a problem for our transaction-aware cache
or the ability to interleave transactions and transactionless
operations). It should still work anyways... but it looks suspicious.

Also, are you putting that delay in place because otherwise the task
begins right away and conflicts with the original transaction? With a
properly transactionally enqueued task, that isn't an issue - the task
is only activated after the txn commits.

Another thing to try (even if the extra txn parameter to add() works) is call:

ofy().cache(false).transact(...

This will give me a better idea where the problem is.

Question: Do you make any other calls to DatastoreService (the raw
api) anywhere?

Jeff

Jeff Schnitzer

unread,

Jul 27, 2012, 9:08:37 PM7/27/12

to objectify...@googlegroups.com

Ok - let us know if the issue ever comes up again.

I have occasionally seen 'transaction closed' exceptions in local dev
when doing lots of work with task queues - in particular during a
routine that populates my local datastore with sample data. I have
never seen the same problem in production. I suspect an SDK bug
related to parallel task execution.

Jeff

James Courtney

unread,

Mar 28, 2014, 3:17:19 PM3/28/14

to objectify...@googlegroups.com, je...@infohazard.org

Jeff et al.

Have you see these "transaction closed" issues since your posting. I'm seeing them in my test environment where we have unit tests which make REST calls to the devserver creating several datastore entities. At the end of the test, in our tearDown method, we remove all the stuff we created via additional REST calls. Some of these calls to delete objects on the server trigger background tasks (up to 3 it appears). Many of the entities delete fine but more often than not we hit a "transaction closed" exception in a Queue.add call. I've spent yesterday evening and this AM trying to very carefully trace through our code to see if I could see anything suspicious but I'm striking out. FWIW I did try adding the Transaction parameter to the Queue.add calls and the cache(false) qualifier to the ofy() instance used to construct our transaction(s). Any further thoughts would be wonderful.

Jamey

Jeff Schnitzer

unread,

Mar 28, 2014, 3:26:05 PM3/28/14

to objectify...@googlegroups.com

In your test environment make sure you are demarcating your requests
properly by explicitly calling ObjectifyFilter.complete() in the
correct place. This may or may not be at the end of each test
depending on what level you test at, but it's usually a good start.

Another thing is that it's best to avoid calling GAE methods that use
the implicit thread-local transaction, especially in test cases or
places which have somewhat ambiguous request lifecycles (like the
remote api). Don't use the Queue.add(TaskOptions) method, use the
Queue.add(Transaction, TaskOptions) method instead. You can pass in
ofy().getTransaction(), which will be null if there is no transaction.

Probably one of those is causing this issue. Let us know if that helps.

Jeff

> --
> You received this message because you are subscribed to the Google Groups
> "objectify-appengine" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to objectify-appen...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

James Courtney

unread,

Mar 28, 2014, 4:15:25 PM3/28/14

to objectify...@googlegroups.com, je...@infohazard.org

Thanks Jeff,

I am using Queue.add(ofy().getTransaction(), TaskOptions) and we do have the Objectify filter configured for all requests to our system.

Best,

Jamey

Jeff Schnitzer

unread,

Mar 28, 2014, 4:58:43 PM3/28/14

to objectify...@googlegroups.com

Ah, I missed that you're running your tests out-of-process against a
dev instance. Sorry.

I've seen occasionally "transaction closed" when attempting a lot of
concurrent operations against entity groups via the task queue. I can
actually force this to happen in production. I'm not sure if it's an
issue with Objectify or an issue with GAE, but the tasks retry and
complete.

Can you send me a complete stacktrace?

Jeff

James Courtney

unread,

Mar 28, 2014, 8:06:23 PM3/28/14

to objectify...@googlegroups.com, je...@infohazard.org

Hey Jeff, here 'tis:

[INFO] com.google.appengine.api.taskqueue.TransactionalTaskException

[INFO] at com.google.appengine.api.taskqueue.QueueApiHelper.translateError(QueueApiHelper.java:96)

[INFO] at com.google.appengine.api.taskqueue.QueueApiHelper.translateError(QueueApiHelper.java:153)

[INFO] at com.google.appengine.api.taskqueue.QueueApiHelper$1.convertException(QueueApiHelper.java:52)

[INFO] at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:94)

[INFO] at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:86)

[INFO] at com.google.appengine.api.taskqueue.QueueApiHelper.getInternal(QueueApiHelper.java:72)

[INFO] at com.google.appengine.api.taskqueue.QueueImpl.add(QueueImpl.java:446)

[INFO] at com.philanthropal.common.background.BackgroundTaskManager.enqueue2(BackgroundTaskManager.java:228)

[INFO] at com.philanthropal.common.background.BackgroundTaskManager.enqueue(BackgroundTaskManager.java:180)

[INFO] at com.philanthropal.common.background.BackgroundTaskManager$2.run(BackgroundTaskManager.java:122)

[INFO] at com.googlecode.objectify.impl.TransactorNo.transactOnce(TransactorNo.java:118)

[INFO] at com.googlecode.objectify.impl.TransactorNo.transactNew(TransactorNo.java:95)

[INFO] at com.googlecode.objectify.impl.TransactorNo.transact(TransactorNo.java:85)

[INFO] at com.googlecode.objectify.impl.ObjectifyImpl.transact(ObjectifyImpl.java:177)

[INFO] at com.philanthropal.common.persistence.OfyService.transact(OfyService.java:65)

[INFO] at com.philanthropal.common.persistence.PersistManager.delete(PersistManager.java:128)

[INFO] at com.philanthropal.common.persistence.TopLevelPersistManager.delete(TopLevelPersistManager.java:43)

[INFO] at com.philanthropal.server.resource.EntityManagerResourceBase.delete(EntityManagerResourceBase.java:108)

[INFO] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

[INFO] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

[INFO] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

[INFO] at java.lang.reflect.Method.invoke(Method.java:601)

[INFO] at com.google.appengine.tools.development.agent.runtime.Runtime.invoke(Runtime.java:115)

[INFO] at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)

[INFO] at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)

[INFO] at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)

[INFO] at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)

[INFO] at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)

[INFO] at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)

[INFO] at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)

[INFO] at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)

[INFO] at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)

[INFO] at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)

[INFO] at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)

[INFO] at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)

[INFO] at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)

[INFO] at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)

[INFO] at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)

[INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)

[INFO] at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)

[INFO] at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)

[INFO] at com.googlecode.objectify.cache.AsyncCacheFilter.doFilter(AsyncCacheFilter.java:59)

[INFO] at com.googlecode.objectify.ObjectifyFilter.doFilter(ObjectifyFilter.java:49)