java.util.concurrent.CancellationException while s

Question

I'm trying to process a big excel file with more than 20K rows. Each row should be saved as an Entity in Datastore. First, I get the excel file in my servlet using the Blobstore and then I queue a task using the Task Queue service. This task, reads the excel file, convert each line in an Entity and store it. As I said before, Excel file could have more than 20K rows. After a while I get this exception:

com.xxx.xxx.ProcessBlob doPost: |POST|ProcessBlob|Exception:Task was cancelled.|Msg:Task was cancelled.|Stack:java.util.concurrent.CancellationException: Task was cancelled.

    at com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:796)
    at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:475)
    at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:381)
    at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:85)
    at com.google.appengine.tools.development.TimedFuture.get(TimedFuture.java:42)
    at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:88)
    at com.google.appengine.api.datastore.Batcher$ReorderingMultiFuture.get(Batcher.java:131)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:88)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:88)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:88)
    at com.google.appengine.api.datastore.FutureHelper.getInternal(FutureHelper.java:75)
    at com.google.appengine.api.datastore.FutureHelper.quietGet(FutureHelper.java:35)
    at com.google.appengine.api.datastore.DatastoreServiceImpl.put(DatastoreServiceImpl.java:56)
    at com.xxx.xxx.xxx.createEntity(EntityService.java:87)
    at com.xxx.xxx.ProcessBlob.doPost(ProcessBlob.java:145)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
    at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.runtime.jetty.SaveSessionFilter.doFilter(SaveSessionFilter.java:35)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.utils.servlet.JdbcMySqlConnectionCleanupFilter.doFilter(JdbcMySqlConnectionCleanupFilter.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 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.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:254)
    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.headerComplete(HttpConnection.java:923)
    at com.google.apphosting.runtime.jetty.RpcRequestParser.parseAvailable(RpcRequestParser.java:76)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:146)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:527)
    at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:437)
    at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:444)
    at com.google.tracing.CurrentContext.runInContext(CurrentContext.java:220)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:308)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:300)
    at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:441)
    at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
    at java.lang.Thread.run(Thread.java:724)

Caused by: java.util.concurrent.CancellationException: Future.cancel() was called.
    at com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:514)
    at com.google.appengine.tools.development.TimedFuture.cancel(TimedFuture.java:85)
    at com.google.common.util.concurrent.ForwardingFuture.cancel(ForwardingFuture.java:48)
    at com.google.apphosting.runtime.ApiProxyImpl$AsyncApiFuture.cancel(ApiProxyImpl.java:553)
    at com.google.apphosting.runtime.RequestManager.cancelPendingAsyncFutures(RequestManager.java:626)
    at com.google.apphosting.runtime.RequestManager.sendDeadline(RequestManager.java:399)
    at com.google.apphosting.runtime.RequestManager.sendDeadline(RequestManager.java:357)
    at com.google.apphosting.runtime.CloneControllerImpl.sendDeadline(CloneControllerImpl.java:201)
    at com.google.apphosting.sandbox.ModelClonePb$CloneController$ServiceParameters$3.handleRequest(ModelClonePb.java:1166)
    at com.google.net.rpc3.impl.server.RpcServerInternalContext.runRpcInApplication(RpcServerInternalContext.java:558)
    at com.google.net.rpc3.impl.server.RpcServerChannel$1.run(RpcServerChannel.java:871)
    at com.google.tracing.LocalTraceSpanRunnable.run(LocalTraceSpanRunnable.java:56)
    at com.google.tracing.LocalTraceSpanBuilder.internalContinueSpan(LocalTraceSpanBuilder.java:626)
    at com.google.net.rpc3.impl.server.RpcServerChannel.startRpc(RpcServerChannel.java:837)
    at com.google.net.rpc3.impl.server.RpcServerChannel.receivedMessage(RpcServerChannel.java:594)
    at com.google.net.rpc3.impl.server.RpcServerChannel.access$2700(RpcServerChannel.java:164)
    at com.google.net.rpc3.impl.server.RpcServerChannel$TransportCallback.receivedMessage(RpcServerChannel.java:2365)
    at com.google.net.rpc3.impl.wire.RpcBaseTransport.receivedMessage(RpcBaseTransport.java:457)
    at com.google.apphosting.runtime.udrpc.UdrpcTransport$ServerAdapter.receivedMessage(UdrpcTransport.java:707)
    at com.google.apphosting.runtime.udrpc.UdrpcTransport.dispatchPacket(UdrpcTransport.java:384)
    at com.google.apphosting.runtime.udrpc.UdrpcTransport.readPackets(UdrpcTransport.java:283)
    at com.google.apphosting.runtime.udrpc.UdrpcTransport$1.run(UdrpcTransport.java:100)
    at com.google.net.eventmanager.AbstractFutureTask$Sync.innerRun(AbstractFutureTask.java:260)
    at com.google.net.eventmanager.AbstractFutureTask.run(AbstractFutureTask.java:121)
    at com.google.net.eventmanager.EventManagerImpl.runTask(EventManagerImpl.java:594)
    at com.google.net.eventmanager.EventManagerImpl.internalRunWorkerLoop(EventManagerImpl.java:1011)
    at com.google.net.eventmanager.EventManagerImpl.runWorkerLoop(EventManagerImpl.java:892)
    at com.google.net.eventmanager.WorkerThreadInfo.runWorkerLoop(WorkerThreadInfo.java:161)
    at com.google.net.eventmanager.EventManagerImpl$WorkerThread.run(EventManagerImpl.java:1879)

Another "weird" thing is that, seeing the logs for the requests, the parameters "ms" and "cpu_ms" are nearly the same when it drops that exception. Maybe I'm going above the AppEngine limits or timeout limits?

[02/Mar/2015:21:11:32 -0800] "POST /tasks/ProcessBlob HTTP/1.1" 200 0 "http://xxx.appspot.com/upload" "AppEngine-Google; (+http://code.google.com/appengine)" "xxx.appspot.com" ms=599492 cpu_ms=32522 queue_name=default task_name=xxx instance=xxx app_engine_release=1.9.18

[02/Mar/2015:23:21:55 -0800] "POST /tasks/ProcessBlob HTTP/1.1" 200 0 "http://xxx.appspot.com/upload" "AppEngine-Google; (+http://code.google.com/appengine)" "xxx.appspot.com" ms=599420 cpu_ms=33262 queue_name=default task_name=xxx instance=xxx app_engine_release=1.9.18

Answer 1

Looks like you faced Task Queue limits, 599949ms == 10 minutes. As per doc:

Tasks targeted at an automatic scaled module must finish execution within 10 minutes. If you have tasks that require more time or computing resources, they can be sent to manual or basic scaling modules, where they can run up to 24 hours.

See docs: https://cloud.google.com/appengine/docs/java/taskqueue/overview-push#task_deadlines

I suggest to split task into few smaller tasks, say one task per 1000 records, maybe smaller