search

GoogleCloudPlatform / appengine-java-vm-runtime

Apache License 2.0
67 stars 34 forks source link

issue with the local GAE execution #151

Open ludoch opened 8 years ago

ludoch commented 8 years ago

See SO entry at http://stackoverflow.com/questions/34620186/failing-to-run-zk-spreadsheet-on-app-engine-managed-vm

GabiAxel commented 8 years ago

Here is an example application to reproduce the problem: https://github.com/GabiAxel/zss-vm

GabiAxel commented 8 years ago

Just noticed the issue title - it happens both locally and in deployment.

A hunch: one difference I noticed between the environments is that GAE uses the datastore for storing the sessions. I configured ZK to use clustered sessions, but maybe something is not right there. Nothing in the logs about that though.

janbartel commented 8 years ago

@ludoch I've verified that the error occurs when using mvn gcloud:run, but not when deploying to a standard jetty 9.2.10 distribution.

I've pursued various avenues of investigation:

I'm running out of ways to investigate this with the tools I've got. I'd like to try to use the new jetty work that @gregw has been doing in the #140 branch, but it is missing the app-engine services like memcache and datastore. Is there any way that we could get those into that branch so that it would be a complete environment to run the webapp in? That way it could be debugged a little easier.

Failing that, do you have any other suggestions for how to debug this? As the zk spreadsheet stuff is closed-source, its extremely difficult to work with.

For the record, when running locally with mvn gcloud:run, I can always get the webapp to fail with the following errors (note that the name of the css file mutates with every new run):

[INFO] SEVERE: Failed to load media, /view/z_mu10/aQJZ1/1ic/0/ss_aQJZ1_f0_sheet_0.css [INFO] java.lang.NullPointerException [INFO] at org.zkoss.zss.ui.Spreadsheet.getMergeMatrixHelper(Spreadsheet.java:2755) [INFO] at org.zkoss.zss.ui.Spreadsheet.prepareBasicStyleSheet(Spreadsheet.java:4144) [INFO] at org.zkoss.zss.ui.Spreadsheet.getSheetDefaultRules0(Spreadsheet.java:4603) [INFO] at org.zkoss.zss.ui.Spreadsheet.getSheetDefaultRules(Spreadsheet.java:4597) [INFO] at org.zkoss.zss.ui.Spreadsheet.access$6200(Spreadsheet.java:219) [INFO] at org.zkoss.zss.ui.Spreadsheet$ExtraCtrl.getMedia(Spreadsheet.java:3041) [INFO] at org.zkoss.zk.au.http.AuDynaMediar.service(AuDynaMediar.java:128) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:459) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:618) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [INFO] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669) [INFO] at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.runtime.jetty9.SaveSessionFilter.doFilter(SaveSessionFilter.java:37) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [INFO] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:553) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [INFO] at com.google.apphosting.vmruntime.jetty9.VmRuntimeWebAppContext.doScope(VmRuntimeWebAppContext.java:299) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [INFO] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) [INFO] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110) [INFO] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [INFO] at org.eclipse.jetty.server.Server.handle(Server.java:497) [INFO] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [INFO] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [INFO] at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [INFO] at java.lang.Thread.run(Thread.java:745)

[INFO] SEVERE: [INFO] java.lang.NullPointerException [INFO] at org.zkoss.zss.ui.au.in.FetchActiveRangeCommand.process(FetchActiveRangeCommand.java:57) [INFO] at org.zkoss.zss.ui.Spreadsheet.service(Spreadsheet.java:5876) [INFO] at org.zkoss.zk.ui.impl.DesktopImpl.service(DesktopImpl.java:710) [INFO] at org.zkoss.zk.ui.impl.UiEngineImpl.execUpdate(UiEngineImpl.java:1249) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.process(DHtmlUpdateServlet.java:611) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:485) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doPost(DHtmlUpdateServlet.java:494) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:644) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [INFO] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669) [INFO] at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.runtime.jetty9.SaveSessionFilter.doFilter(SaveSessionFilter.java:37) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [INFO] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:553) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [INFO] at com.google.apphosting.vmruntime.jetty9.VmRuntimeWebAppContext.doScope(VmRuntimeWebAppContext.java:299) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [INFO] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) [INFO] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110) [INFO] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [INFO] at org.eclipse.jetty.server.Server.handle(Server.java:497) [INFO] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [INFO] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [INFO] at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [INFO] at java.lang.Thread.run(Thread.java:745)

ludoch commented 8 years ago

This is why you can try next: 1/ build a jettyhome and jettybase from the branch Greg is working on 2/ make sure quickstart is not used (i.e non annotated servlets) or ask Greg his workaround 3/ set up these 2 env variables to the correct location of 1/

APP_ENGINE_JETTY_BASE

and

APP_ENGINE_JETTY_HOME

4/ run mvn gcloud:run that will provide stub API services to test against. The issue might be in this layer (poor session management?) or already fixed in the lastest branch we are working on.

On Wed, Jan 6, 2016 at 11:36 PM, Jan Bartel notifications@github.com wrote:

@ludoch https://github.com/ludoch I've verified that the error occurs when using mvn gcloud:run, but not when deploying to a standard jetty 9.2.10 distribution.

I've pursued various avenues of investigation:

  • I configured the standard jetty distro to use jdb session persistance - to quickly verify that the session is serializable - and the app works fine
  • I configured the standard jetty distro to use a remote gcloud datastore for session persistance (one of the new jetty session managers I've been working on), and again the app works fine

I'm running out of ways to investigate this with the tools I've got. I'd like to try to use the new jetty work that @gregw https://github.com/gregw has been doing in the #140 https://github.com/GoogleCloudPlatform/appengine-java-vm-runtime/issues/140 branch, but it is missing the app-engine services like memcache and datastore. Is there any way that we could get those into that branch so that it would be a complete environment to run the webapp in? That way it could be debugged a little easier.

Failing that, do you have any other suggestions for how to debug this? As the zk spreadsheet stuff is closed-source, its extremely difficult to work with.

For the record, when running locally with mvn gcloud:run, I can always get the webapp to fail with the following errors (note that the name of the css file mutates with every new run):

[INFO] SEVERE: Failed to load media, /view/z_mu10/aQJZ1/1ic/0/ss_aQJZ1_f0_sheet_0.css [INFO] java.lang.NullPointerException [INFO] at org.zkoss.zss.ui.Spreadsheet.getMergeMatrixHelper(Spreadsheet.java:2755) [INFO] at org.zkoss.zss.ui.Spreadsheet.prepareBasicStyleSheet(Spreadsheet.java:4144) [INFO] at org.zkoss.zss.ui.Spreadsheet.getSheetDefaultRules0(Spreadsheet.java:4603) [INFO] at org.zkoss.zss.ui.Spreadsheet.getSheetDefaultRules(Spreadsheet.java:4597) [INFO] at org.zkoss.zss.ui.Spreadsheet.access$6200(Spreadsheet.java:219) [INFO] at org.zkoss.zss.ui.Spreadsheet$ExtraCtrl.getMedia(Spreadsheet.java:3041) [INFO] at org.zkoss.zk.au.http.AuDynaMediar.service(AuDynaMediar.java:128) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:459) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:618) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [INFO] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669) [INFO] at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.runtime.jetty9.SaveSessionFilter.doFilter(SaveSessionFilter.java:37) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [INFO] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:553) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [INFO] at com.google.apphosting.vmruntime.jetty9.VmRuntimeWebAppContext.doScope(VmRuntimeWebAppContext.java:299) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [INFO] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) [INFO] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110) [INFO] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [INFO] at org.eclipse.jetty.server.Server.handle(Server.java:497) [INFO] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [INFO] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [INFO] at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [INFO] at java.lang.Thread.run(Thread.java:745)

[INFO] SEVERE: [INFO] java.lang.NullPointerException [INFO] at org.zkoss.zss.ui.au.in.FetchActiveRangeCommand.process(FetchActiveRangeCommand.java:57) [INFO] at org.zkoss.zss.ui.Spreadsheet.service(Spreadsheet.java:5876) [INFO] at org.zkoss.zk.ui.impl.DesktopImpl.service(DesktopImpl.java:710) [INFO] at org.zkoss.zk.ui.impl.UiEngineImpl.execUpdate(UiEngineImpl.java:1249) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.process(DHtmlUpdateServlet.java:611) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:485) [INFO] at org.zkoss.zk.au.http.DHtmlUpdateServlet.doPost(DHtmlUpdateServlet.java:494) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:644) [INFO] at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [INFO] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669) [INFO] at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.runtime.jetty9.SaveSessionFilter.doFilter(SaveSessionFilter.java:37) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43) [INFO] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [INFO] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:553) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) [INFO] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [INFO] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [INFO] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) [INFO] at com.google.apphosting.vmruntime.jetty9.VmRuntimeWebAppContext.doScope(VmRuntimeWebAppContext.java:299) [INFO] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [INFO] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) [INFO] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110) [INFO] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [INFO] at org.eclipse.jetty.server.Server.handle(Server.java:497) [INFO] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [INFO] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [INFO] at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [INFO] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [INFO] at java.lang.Thread.run(Thread.java:745)

— Reply to this email directly or view it on GitHub https://github.com/GoogleCloudPlatform/appengine-java-vm-runtime/issues/151#issuecomment-169586491 .

janbartel commented 8 years ago

@ludoch thanks for that tip. I've now been able to successfully run the gcloud plugin against Greg's new jetty-home and jetty-base from the #140 branch. Some tips documented here to make it work:

  1. follow @ludoch's steps from previous post
  2. configure the gcloud plugin to pass into the jetty invocation an explicit location for the logs and the exact location of the webapp:
       <jvm_flag>
           <param>-Dcom.google.apphosting.logs=/tmp</param>
           <param>-Droot.webapp=/this/is/my/test-webapp/target/test-webapp</param>
       </jvm_flag>

Using the #140 branch I've been able to produce more and better debug output. It is apparent that:

Based on those observations above, I suspect that the architecture of the appengine session manager maybe the cause of the problem: as I mentioned in a prior email exchange, the architecture is such that multiple simultaneous requests do NOT share the same session object, but rather distinct different instances. This is one of the major differences between appengine jetty and the jetty distro. To test this theory, I'll replace the appengine session manager with the standard jetty session managers (I'll try both non-clustered and clustered). I'll post my results shortly.

janbartel commented 8 years ago

I can confirm that replacing the appengine session manager with either the jetty HashSessionManager (non-clustering) or the JDBCSessionManager (clustering) makes the app work.

gregw commented 8 years ago

Is there a particular reason that the GAE session manager does not share session instances within an instance? If not, then we could make the new session manager being developed for memcache/gcloud available in compat - this would fix this issue... unless the multiple requests were spread over multiple instances - in which case there could be problems anyway.

gregw commented 8 years ago

Marked as an enhancement - ie that compat should use a session manager that shares instances withing the same instance. This is supported by the new session manager in jetty-9.4 that can use both gcloud datastore and memecache in a more standard fashion,

GabiAxel commented 8 years ago

I did some more experimentation. I tried using the "vanilla" Jetty runtime with default automatic scaling and got another exception about session timeout. Then I switched to manual scaling and it worked fine. I understand that manual scaling is closer to a non-clustered environment so the session is not clustered across instances and the problem doesn't happen.

I suggest documenting this to make it clearer to new users. I think a matrix showing how each combination (runtime type - compat or vanilla, scaling - automatic or manual, and other possible configurations) behaves in manner of session clustering (or lack of clustering).

Anyway for my case it would be acceptable to use the vanilla runtime, but I much prefer to have session clustering and automatic scaling. Is there a configuration that I could use? Would that be a matter of customising Dockerfile or something more?

gregw commented 8 years ago

@GabiAxel I'm working on an example for #188 that will show how to add a pure gcloud session manager to the jetty9 image. Unfortunately that configuration also has problems as it doesn't use mem-cache to pull session changes between nodes, thus without a sticky load balancer there is a risk of stale sessions. The example has a 1sec stale timeout, but that is a large window for new requests on a different instance to not see changes!

The Jetty-9.4 session manager will allow both shared sessions within an instance and immediate passivation once all requests drain from an instance. However, this could still result in stale sessions if a constant stream of requests is spread over multiple nodes such that the request count never goes to 0.

I guess the approach in GAEv1 and current compat of not sharing sessions and always retrieving from mem cache is an attempt to avoid such stale sessions, but it has the not-share-within-instance problem.

Unfortunately given the poorly defined semantics of the servlet session spec, I'm not sure there is a silver bullet here!