GAE/J-Blaze接続でInvocationTargetExceptionがよく起こる

クライアントのAirアプリからGAE/JのサーバーにアクセスするとよくInvocationTargetExceptionが起こる。

発生するタイミングとしては、アイドルタイムが10分以上経ったりなど、しばらくしてからサーバーへリクエストを発生した時によく起こる。というか必ず起こっている。

ログのレベルとしてはInfoレベルなのだが、Air上でも一瞬「うっ」とリクエストが止まったように見えて、なんだか気になる。

xxx.xxx.xxx.xxx - - [13/Sep/2009:18:47:23 -0700] "POST /messagebroker/amf;jsessionid=Z6NYw5g89TFfOj6cDi50aA HTTP/1.1" 200 960 "app:/xxx.swf" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en) AppleWebKit/526.9+ (KHTML, like Gecko) AdobeAIR/1.5,gzip(gfe)" "xxx.appspot.com"

I 09-13 06:47PM 22.601

com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue$SystemLoader loadFinalizer: Not allowed to access system class loader.

I 09-13 06:47PM 22.614

com.google.appengine.repackaged.com.google.common.base.internal.Finalizer getInheritableThreadLocalsField: Couldn't access Thread.inheritableThreadLocals. Reference finalizer threads will inherit thread local values.

I 09-13 06:47PM 22.616

com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue <init>: Failed to start reference finalizer thread. Reference cleanup will only occur when new references are created.
java.lang.reflect.InvocationTargetException
 at com.google.appengine.runtime.Request.process-1ed2a922d6cd3b28(Request.java)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
 at java.lang.reflect.Method.invoke(Method.java:40)
 at com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue.<init>(FinalizableReferenceQueue.java:124)
 at com.google.appengine.repackaged.com.google.common.labs.misc.InterningPools$WeakInterningPool.<clinit>(InterningPools.java:104)
 at com.google.appengine.repackaged.com.google.common.labs.misc.InterningPools.newWeakInterningPool(InterningPools.java:48)
 at com.google.appengine.repackaged.com.google.io.protocol.ProtocolSupport.<clinit>(ProtocolSupport.java:55)
 at com.google.apphosting.api.DatastorePb$Query.<init>(DatastorePb.java:1072)
 at com.google.apphosting.api.DatastorePb$Query$1.<init>(DatastorePb.java:2355)
 at com.google.apphosting.api.DatastorePb$Query.<clinit>(DatastorePb.java:2355)
 at com.google.appengine.api.datastore.QueryTranslator.convertToPb(QueryTranslator.java:27)
 at com.google.appengine.api.datastore.DatastoreServiceImpl$PreparedQueryImpl.convertToPb(DatastoreServiceImpl.java:357)
 at com.google.appengine.api.datastore.DatastoreServiceImpl$PreparedQueryImpl.runQuery(DatastoreServiceImpl.java:339)
 at com.google.appengine.api.datastore.DatastoreServiceImpl$PreparedQueryImpl.access$100(DatastoreServiceImpl.java:269)
 at com.google.appengine.api.datastore.DatastoreServiceImpl$PreparedQueryImpl$1.iterator(DatastoreServiceImpl.java:303)
 at org.datanucleus.store.appengine.query.RuntimeExceptionWrappingIterable.iterator(RuntimeExceptionWrappingIterable.java:42)
 at org.datanucleus.store.appengine.query.StreamingQueryResult.<init>(StreamingQueryResult.java:77)
 at org.datanucleus.store.appengine.query.DatastoreQuery.newStreamingQueryResultForEntities(DatastoreQuery.java:324)
 at org.datanucleus.store.appengine.query.DatastoreQuery.fulfillEntityQuery(DatastoreQuery.java:310)
 at org.datanucleus.store.appengine.query.DatastoreQuery.performExecute(DatastoreQuery.java:242)
 at org.datanucleus.store.appengine.query.JDOQLQuery.performExecute(JDOQLQuery.java:84)
 at org.datanucleus.store.query.Query.executeQuery(Query.java:1489)
 at org.datanucleus.store.query.Query.executeWithArray(Query.java:1371)
 at org.datanucleus.jdo.JDOQuery.execute(JDOQuery.java:266)
 at jp.co.tricell.sonicboom.rpc.MutterUtils.getMutterAround(MutterUtils.java:84)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
 at java.lang.reflect.Method.invoke(Method.java:40)
 at flex.messaging.services.remoting.adapters.JavaAdapter.invoke(JavaAdapter.java:421)
 at flex.messaging.services.RemotingService.serviceMessage(RemotingService.java:183)
 at flex.messaging.MessageBroker.routeMessageToService(MessageBroker.java:1503)
 at flex.messaging.endpoints.AbstractEndpoint.serviceMessage(AbstractEndpoint.java:884)
 at flex.messaging.endpoints.amf.MessageBrokerFilter.invoke(MessageBrokerFilter.java:121)
 at flex.messaging.endpoints.amf.LegacyFilter.invoke(LegacyFilter.java:158)
 at flex.messaging.endpoints.amf.SessionFilter.invoke(SessionFilter.java:44)
 at flex.messaging.endpoints.amf.BatchProcessFilter.invoke(BatchProcessFilter.java:67)
 at flex.messaging.endpoints.amf.SerializationFilter.invoke(SerializationFilter.java:146)
 at flex.messaging.endpoints.BaseHTTPEndpoint.service(BaseHTTPEndpoint.java:278)
 at flex.messaging.MessageBrokerServlet.service(MessageBrokerServlet.java:322)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:806)
 at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
 at com.google.apphosting.runtime.jetty.SaveSessionFilter.doFilter(SaveSessionFilter.java:35)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
 at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
 at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
 at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
 at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
 at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712)
 at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
 at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:237)
 at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
 at org.mortbay.jetty.Server.handle(Server.java:313)
 at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
 at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:830)
 at com.google.apphosting.runtime.jetty.RpcRequestParser.parseAvailable(RpcRequestParser.java:76)
 at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
 at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:139)
 at com.google.apphosting.runtime.JavaRuntime.handleRequest(JavaRuntime.java:235)
 at com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:4950)
 at com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:4948)
 at com.google.net.rpc.impl.BlockingApplicationHandler.handleRequest(BlockingApplicationHandler.java:24)
 at com.google.net.rpc.impl.RpcUtil.runRpcInApplication(RpcUtil.java:359)
 at com.google.net.rpc.impl.Server$2.run(Server.java:823)
 at com.google.tracing.LocalTraceSpanRunnable.run(LocalTraceSpanRunnable.java:56)
 at com.google.tracing.LocalTraceSpanBuilder.internalContinueSpan(LocalTraceSpanBuilder.java:516)
 at com.google.net.rpc.impl.Server.startRpc(Server.java:778)
 at com.google.net.rpc.impl.Server.processRequest(Server.java:351)
 at com.google.net.rpc.impl.ServerConnection.messageReceived(ServerConnection.java:437)
 at com.google.net.rpc.impl.RpcConnection.parseMessages(RpcConnection.java:319)
 at com.google.net.rpc.impl.RpcConnection.dataReceived(RpcConnection.java:290)
 at com.google.net.async.Connection.handleReadEvent(Connection.java:428)
 at com.google.net.async.EventDispatcher.processNetworkEvents(EventDispatcher.java:762)
 at com.google.net.async.EventDispatcher.internalLoop(EventDispatcher.java:207)
 at com.google.net.async.EventDispatcher.loop(EventDispatcher.java:101)
 at com.google.net.rpc.RpcService.runUntilServerShutdown(RpcService.java:251)
 at com.google.apphosting.runtime.JavaRuntime$RpcRunnable.run(JavaRuntime.java:392)
 at java.lang.Thread.run(Unknown Source)
Caused by: java.security.AccessControlException: access denied (java.lang.RuntimePermission modifyThreadGroup)
 at java.security.AccessControlContext.checkPermission(Unknown Source)
 at java.security.AccessController.checkPermission(Unknown Source)
 at java.lang.SecurityManager.checkPermission(Unknown Source)
 at java.lang.ThreadGroup.checkAccess(Unknown Source)
 at java.lang.Thread.init(Unknown Source)
 at java.lang.Thread.<init>(Unknown Source)
 at com.google.appengine.repackaged.com.google.common.base.internal.Finalizer.<init>(Finalizer.java:96)
 at com.google.appengine.repackaged.com.google.common.base.internal.Finalizer.startFinalizer(Finalizer.java:82)
 ... 81 more

上記のログには3種類のInfoレベルのログが含まれており、最後の3つ目のInfoレベルのものがInvocationTargetExceptionなのだが、この3種類のものが必ずアイドルタイム発生後に発生する。

InvocationTargetExceptionは、JavaDocによると「呼び出されるメソッドまたはコンストラクタがスローする例外をラップする、チェック済み例外」ということ。問題なのはログの下の方にある、原因となった「Caused by～」のほうだが、securityのAccessControlExceptionということで、これはGAE/J上でスレッドなどを走らせようとしたときによく出る例外だったなぁと思いだす。

Airから接続して前回のセッションを呼び出そうとした時にスレッドを使おうとしてExceptionが発生しているのかもしれない。もともとBlazeDSのRemoting Objectもコードを改変してムリクリ動かしているわけで(^^;)。

動作上は、ちょっとリクエストがつっかえたように見えるというくらいで、その他は期待したとおりの動作が出来ているので問題はないのだが・・・。

毎回このログが出ないようにできれば改善したい。どうにかできんもんかのー。