3
votes

All versions of my app suddenly stopped working.

Similar to Unable to load several versions of AppEngine Project and Seeing HardDeadLineExceeded Exceptions

From the logs:

Failed startup of context com.google.apphosting.utils.jetty.RuntimeAppEngineWebAppContext@7881db{/,/base/data/home/apps/[MY_APP]/946.357282374521459350}
com.google.apphosting.api.DeadlineExceededException: This request (d505d1e88148a047) started at 2012/03/08 04:17:00.300 UTC and was still executing at 2012/03/08 04:18:00.917 UTC.
    at java.util.zip.ZipFile.read(Native Method)
    at java.util.zip.ZipFile.access$1200(ZipFile.java:57)
    at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:476)
    at java.util.zip.ZipFile$1.fill(ZipFile.java:259)
    at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:158)
    at java.io.DataInputStream.readFully(DataInputStream.java:195)
    at java.util.jar.JarFile.hasClassPathAttribute(JarFile.java:482)
    at java.util.jar.JavaUtilJarAccessImpl.jarFileHasClassPathAttribute(JavaUtilJarAccessImpl.java:33)
    at sun.misc.URLClassPath$JarLoader.getClassPath(URLClassPath.java:1176)
    at sun.misc.URLClassPath.getLoader(URLClassPath.java:374)
    at sun.misc.URLClassPath.findResource(URLClassPath.java:201)
    at java.net.URLClassLoader$2.run(URLClassLoader.java:379)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findResource(URLClassLoader.java:376)
    at com.google.apphosting.runtime.security.UserClassLoader.findResource(UserClassLoader.java:723)
    at java.lang.ClassLoader.getResource(ClassLoader.java:977)
    at org.mortbay.resource.Resource.newSystemResource(Resource.java:203)
    at org.mortbay.jetty.webapp.WebXmlConfiguration.configureDefaults(WebXmlConfiguration.java:159)
    at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1230)
    at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517)
    at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467)
    at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:202)
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:171)
    at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:422)
    at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:449)
    at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:455)
    at com.google.tracing.TraceContext.runInContext(TraceContext.java:695)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:333)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:325)
    at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:453)
    at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
    at java.lang.Thread.run(Thread.java:679)
C 2012-03-07 23:18:01.030
Uncaught exception from servlet
javax.servlet.UnavailableException: Initialization failed.
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:211)
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:171)
    at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:422)
    at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:449)
    at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:455)
    at com.google.tracing.TraceContext.runInContext(TraceContext.java:695)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:333)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:325)
    at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:453)
    at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
    at java.lang.Thread.run(Thread.java:679)


Also, seen in browser:


Uncaught exception from servlet
javax.servlet.UnavailableException: Initialization failed.
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:211)
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:171)
    at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123)
    at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:422)
    at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:449)
    at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:455)
    at com.google.tracing.TraceContext.runInContext(TraceContext.java:695)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:333)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:325)
    at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:453)
    at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
    at java.lang.Thread.run(Thread.java:679)

Another error in the logs:

2012-03-08 12:28:26.248 com.google.inject.internal.util.$FinalizableReferenceQueue$SystemLoader loadFinalizer: Not allowed to access system class loader. I 2012-03-08 12:28:27.143 com.google.inject.internal.util.$FinalizableReferenceQueue : 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-58eed86e9936f59f(Request.java) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:43) at com.google.inject.internal.util.$FinalizableReferenceQueue.(FinalizableReferenceQueue.java:124) at com.google.inject.internal.util.$MapMaker$QueueHolder.(MapMaker.java:787) at com.google.inject.internal.util.$MapMaker$WeakEntry.(MapMaker.java:946) at com.google.inject.internal.util.$MapMaker$Strength$1.newEntry(MapMaker.java:312) at com.google.inject.internal.util.$MapMaker$StrategyImpl.newEntry(MapMaker.java:498) at com.google.inject.internal.util.$MapMaker$StrategyImpl.newEntry(MapMaker.java:419) at com.google.inject.internal.util.$CustomConcurrentHashMap$ComputingImpl.get(CustomConcurrentHashMap.java:2029) at com.google.inject.internal.Annotations$AnnotationChecker.hasAnnotations(Annotations.java:116) at com.google.inject.internal.Annotations.isBindingAnnotation(Annotations.java:180) at com.google.inject.internal.Annotations.findBindingAnnotation(Annotations.java:161) at com.google.inject.internal.ProviderMethodsModule.getKey(ProviderMethodsModule.java:129) at com.google.inject.internal.ProviderMethodsModule.createProviderMethod(ProviderMethodsModule.java:116) at com.google.inject.internal.ProviderMethodsModule.getProviderMethods(ProviderMethodsModule.java:83) at com.google.inject.internal.ProviderMethodsModule.configure(ProviderMethodsModule.java:73) at com.google.inject.spi.Elements$RecordingBinder.install(Elements.java:223) at com.google.inject.spi.Elements$RecordingBinder.install(Elements.java:232) at com.google.inject.spi.Elements.getElements(Elements.java:101) at com.google.inject.internal.InjectorShell$Builder.build(InjectorShell.java:133) at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:103) at com.google.inject.Guice.createInjector(Guice.java:95) at com.google.inject.Guice.createInjector(Guice.java:72) at com.google.inject.Guice.createInjector(Guice.java:62) at [MYAPP].server.guice.GuiceInjectorFactory$GuiceBerry.getInjector(GuiceInjectorFactory.java:20) at [MYAPP].server.guice.GuiceInjectorFactory.getInjector(GuiceInjectorFactory.java:29) at com.google.inject.servlet.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:45) at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:548) at org.mortbay.jetty.servlet.Context.startContext(Context.java:136) at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1250) at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517) at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467) at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50) at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:449) at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:455) at com.google.tracing.TraceContext.runInContext(TraceContext.java:695) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:333) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:325) at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:453) at java.lang.Thread.run(Thread.java:679) Caused by: java.security.AccessControlException: access denied (java.lang.RuntimePermission modifyThreadGroup) at java.security.AccessControlContext.checkPermission(AccessControlContext.java:355) at java.security.AccessController.checkPermission(AccessController.java:567) at java.lang.SecurityManager.checkPermission(SecurityManager.java:549) at java.lang.ThreadGroup.checkAccess(ThreadGroup.java:315) at java.lang.Thread.init(Thread.java:353) at java.lang.Thread.(Thread.java:479) at com.google.inject.internal.util.$Finalizer.(Finalizer.java:92) at com.google.inject.internal.util.$Finalizer.startFinalizer(Finalizer.java:81) ... 42 more C 2012-03-08 12:28:59.290 Uncaught exception from servlet com.google.apphosting.runtime.HardDeadlineExceededError: This request (58eed86e9936f59f) started at 2012/03/08 17:27:56.854 UTC and was still executing at 2012/03/08 17:28:59.245 UTC. at java.io.FileInputStream.readBytes(Native Method) at java.io.FileInputStream.read(FileInputStream.java:231) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read1(BufferedInputStream.java:275) at java.io.BufferedInputStream.read(BufferedInputStream.java:334) at com.google.inject.internal.asm.$ClassReader.a(Unknown Source) at com.google.inject.internal.asm.$ClassReader.(Unknown Source) at com.google.inject.internal.util.$LineNumbers.(LineNumbers.java:62) at com.google.inject.internal.util.$StackTraceElements$1.apply(StackTraceElements.java:36) at com.google.inject.internal.util.$StackTraceElements$1.apply(StackTraceElements.java:33) at com.google.inject.internal.util.$MapMaker$StrategyImpl.compute(MapMaker.java:549) at com.google.inject.internal.util.$MapMaker$StrategyImpl.compute(MapMaker.java:419) at com.google.inject.internal.util.$CustomConcurrentHashMap$ComputingImpl.get(CustomConcurrentHashMap.java:2041) at com.google.inject.internal.util.$StackTraceElements.forMember(StackTraceElements.java:53) at com.google.inject.internal.Errors.formatSource(Errors.java:690) at com.google.inject.internal.Errors.format(Errors.java:555) at com.google.inject.ProvisionException.getMessage(ProvisionException.java:59) at java.lang.Throwable.getLocalizedMessage(Throwable.java:284) at java.lang.Throwable.toString(Throwable.java:360) at java.lang.String.valueOf(String.java:2838) at java.lang.StringBuffer.append(StringBuffer.java:236) at org.mortbay.component.AbstractLifeCycle.setFailed(AbstractLifeCycle.java:183) at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:56) at org.mortbay.jetty.servlet.ServletHandler.initialize(ServletHandler.java:662) at org.mortbay.jetty.servlet.Context.startContext(Context.java:140) at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1250) at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517) at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467) at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50) at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:202) at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:171) at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:123) at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:422) at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:449) at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:455) at com.google.tracing.TraceContext.runInContext(TraceContext.java:695) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:333) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:325) at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:453) at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251) at java.lang.Thread.run(Thread.java:679) I 2012-03-08 12:28:59.323 This request caused a new process to be started for your application, and thus caused your application code to be loaded for the first time. This request may thus take longer and use more CPU than a typical request for your application. W 2012-03-08 12:28:59.323 A problem was encountered with the process that handled this request, causing it to exit. This is likely to cause a new process to be used for the next request to your application. If you see this message frequently, you may be throwing exceptions during the initialization of your application. (Error code 104)

1
I'm seeing this too, suddenly started to happen. - Nitzan Volman
please fill a bug report to google - cometta
seems to have been reported already. (months ago) code.google.com/p/googleappengine/issues/detail?id=6246#c2 - Nick Siderakis

1 Answers

0
votes

This is likely caused by your application taking too long to start up. While your application is still initializing itself, it exceeds the hard per-request time limit (30 seconds, but in practice apparently more like 60 seconds).

I've seen these as well, and I think it's a combination of your application being expensive to load, and something wrong on AppEngine's side; it appears to take much longer to load classes than it should. So either try slimming down your application, or wait for Google to fix the underlying issue.

The log messages from com.google.inject.internal.util.$FinalizableReferenceQueue$SystemLoader loadFinalizer are a red herring, they are normal when using Guice on AppEngine and shouldn't harm.