スティルハウスの書庫の書庫

はてなダイアリーで書いてた「スティルハウスの書庫」を移転してきました。

謎なエラーを集めてみよう

appengineを運用していると、ときおり原因不明のエラーが起きます。Googleが説明する0.1%程度のエラーとはちょっと違う感じがします。どれも毎回起きるわけじゃなくて、一時的に頻発したりします。想像するに、特定のApp Serverノード上でデプロイやクラスロードがうまく働いていなかったり、特定のデータセンターでmemcacheが不調だったりするのではないでしょうか。そんな謎なスタックトレースを集めてみました(ちなみにクライアント側でリトライするロジックを組んでいるので、繰り返しエラー以外はユーザーさんに大きな影響出てないはずです)。

  • memcacheをgetすると固まる。特定ユーザー(ブラジル)からのリクエストで繰り返し起きるのが謎(ブラジルのデータセンターでmemcacheサービスが不調だったとか?)。MemcacheService#incrementで固まることも多い。他のユーザーは影響なし。
com.google.apphosting.runtime.HardDeadlineExceededError: This request (1e5289f5333d0c9a) started at 2009/09/21 20:35:21.551 UTC and was still executing at 2009/09/21 20:35:51.561 UTC.
	at sun.misc.Unsafe.park(Native Method)
	at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(Unknown Source)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(Unknown Source)
	at java.util.concurrent.CountDownLatch.await(Unknown Source)
	at com.google.net.rpc.util.RpcWaiter.waitForRpcsToFinish(RpcWaiter.java:96)
	at com.google.apphosting.runtime.ApiProxyImpl.doSyncCall(ApiProxyImpl.java:99)
	at com.google.apphosting.runtime.ApiProxyImpl.access$000(ApiProxyImpl.java:36)
	at com.google.apphosting.runtime.ApiProxyImpl$1.run(ApiProxyImpl.java:68)
	at com.google.apphosting.runtime.ApiProxyImpl$1.run(ApiProxyImpl.java:64)
	at java.security.AccessController.doPrivileged(Native Method)
	at com.google.apphosting.runtime.ApiProxyImpl.makeSyncCall(ApiProxyImpl.java:64)
	at com.google.apphosting.runtime.ApiProxyImpl.makeSyncCall(ApiProxyImpl.java:36)
	at com.google.apphosting.api.ApiProxy.makeSyncCall(ApiProxy.java:79)
	at com.google.appengine.api.memcache.MemcacheServiceImpl.makeSyncCall(MemcacheServiceImpl.java:162)
	at com.google.appengine.api.memcache.MemcacheServiceImpl.get(MemcacheServiceImpl.java:233)
	at com.google.appengine.api.memcache.stdimpl.GCache.get(GCache.java:157)
  • XPathの初期化時にクラスローダーで固まる?数回起きた。
com.google.apphosting.runtime.HardDeadlineExceededError: This request (d41d5d55db9ecd53) started at 2009/09/21 20:05:38.123 UTC and was still executing at 2009/09/21 20:06:08.578 UTC.
	at com.google.appengine.runtime.Request.process-7fa0a1fec5c7ff0e(Request.java)
	at sun.jkernel.DownloadManager.isJREComplete(Unknown Source)
	at sun.jkernel.DownloadManager.getBootClassPathEntryForResource(Unknown Source)
	at java.lang.ClassLoader.getBootstrapResource(Unknown Source)
	at java.lang.ClassLoader.getResource(Unknown Source)
	at java.lang.ClassLoader.getResourceAsStream(Unknown Source)
	at org.apache.xml.dtm.SecuritySupport12$6.run(SecuritySupport12.java:121)
	at java.security.AccessController.doPrivileged(AccessController.java:34)
	at org.apache.xml.dtm.SecuritySupport12.getResourceAsStream(SecuritySupport12.java:114)
	at org.apache.xml.dtm.ObjectFactory.findJarServiceProviderName(ObjectFactory.java:544)
	at org.apache.xml.dtm.ObjectFactory.lookUpFactoryClassName(ObjectFactory.java:375)
	at org.apache.xml.dtm.ObjectFactory.lookUpFactoryClass(ObjectFactory.java:208)
	at org.apache.xml.dtm.ObjectFactory.createObject(ObjectFactory.java:133)
	at org.apache.xml.dtm.ObjectFactory.createObject(ObjectFactory.java:103)
	at org.apache.xml.dtm.DTMManager.newInstance(DTMManager.java:137)
	at org.apache.xpath.XPathContext.<init>(XPathContext.java:102)
	at org.apache.xpath.jaxp.XPathExpressionImpl.eval(XPathExpressionImpl.java:115)
	at org.apache.xpath.jaxp.XPathExpressionImpl.eval(XPathExpressionImpl.java:99)
	at org.apache.xpath.jaxp.XPathExpressionImpl.evaluate(XPathExpressionImpl.java:184)
  • BeanUtilsのリフレクションで固まる。これも特定ユーザーで頻発。
com.google.apphosting.api.DeadlineExceededException: This request (dfb5c96f0e57222d) started at 2009/09/21 20:03:45.586 UTC and was still executing at 2009/09/21 20:04:15.066 UTC.
	at sun.reflect.GeneratedMethodAccessor255.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at com.google.apphosting.runtime.security.shared.intercept.java.lang.reflect.Method_$3.run(Method_.java:164)
	at java.security.AccessController.doPrivileged(Native Method)
	at com.google.apphosting.runtime.security.shared.intercept.java.lang.reflect.Method_.privilegedInvoke(Method_.java:162)
	at com.google.apphosting.runtime.security.shared.intercept.java.lang.reflect.Method_.invoke_(Method_.java:131)
	at com.google.apphosting.runtime.security.shared.intercept.java.lang.reflect.Method_.invoke(Method_.java:40)
	at org.apache.commons.beanutils.PropertyUtilsBean.invokeMethod(PropertyUtilsBean.java:2155)
	at org.apache.commons.beanutils.PropertyUtilsBean.setSimpleProperty(PropertyUtilsBean.java:2141)
	at org.apache.commons.beanutils.BeanUtilsBean.copyProperty(BeanUtilsBean.java:439)
	at org.apache.commons.beanutils.BeanUtilsBean.copyProperties(BeanUtilsBean.java:270)
	at org.apache.commons.beanutils.BeanUtils.copyProperties(BeanUtils.java:137)
  • java.lang.NoClassDefFoundError: libにおいたJARファイルのクラスや、自分で書いたアプリ本体のクラスがロードできない。ほかのユーザーは問題ないので、App ServerのノードによってJARがうまくデプロイされてなかったりするのかな?

9/22追記

  • DatastoreのQuery#executeやPersistenceManager#getObjectByIdで固まる。もちろん0.1%程度の頻度なら想定内ですが、これは特定ユーザーのリクエストに限って一時的に繰り返し発生します。こういう現象はこれまで2回くらい目撃したことがあり、いずれもしばらくほっとくと15分くらいで直りました。もしかして、特定エンティティを保持するタブレットサーバーが不調で、フェイルオーバーするのに時間がかかるとか?
com.google.apphosting.runtime.HardDeadlineExceededError: This request (77363889e3250ad3) started at 2009/09/23 03:34:10.080 UTC and was still executing at 2009/09/23 03:34:39.863 UTC.
	at com.google.appengine.runtime.Request.process-108113f39330a770(Request.java)
	at sun.misc.Unsafe.park(Native Method)
	at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(Unknown Source)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(Unknown Source)
	at java.util.concurrent.CountDownLatch.await(Unknown Source)
	at com.google.net.rpc.util.RpcWaiter.waitForRpcsToFinish(RpcWaiter.java:96)
	at com.google.apphosting.api.ApiProxy.makeSyncCall(ApiProxy.java:79)
	at com.google.appengine.api.datastore.DatastoreApiHelper.makeSyncCall(DatastoreApiHelper.java:48)
	at com.google.appengine.api.datastore.DatastoreServiceImpl$PreparedQueryImpl.runQuery(DatastoreServiceImpl.java:342)
	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)