Help troubleshooting running under the development server

[Kevin Wise]

I have an exceptionally strange situation. My web app, running on Guice in a app engine standard environment, works fine in a development environment on Linux or Mac, but doesn't work on Windows. The symptom is that when I try to run the application, it appears to startup, but then always responds with a 500 error. The log reports:

ERROR    2017-02-24 15:06:29,865 http_proxy.py:116] bad runtime process port ['']
INFO     2017-02-24 15:06:29,964 module.py:806] default: "GET / HTTP/1.1" 500 4379

Even stranger, the server returns the log file contents to the browser.  Here is a sample of the browser output:

bad runtime process port ['']

Feb 24, 2017 3:04:52 PM com.google.appengine.tools.development.AbstractContainerService configure
WARNING: Null value for containerConfigProperties.get(devappserver.portMappingProvider)
Feb 24, 2017 3:04:52 PM com.google.apphosting.utils.jetty.JettyLogger info
INFO: Logging to JettyLogger(null) via com.google.apphosting.utils.jetty.JettyLogger
Feb 24, 2017 10:04:52 PM com.google.apphosting.utils.jetty.JettyLogger info
INFO: jetty-6.1.x
Feb 24, 2017 10:05:15 PM org.hibernate.validator.internal.util.Version <clinit>
INFO: HV000001: Hibernate Validator 5.2.4.Final
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider as a provider class
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.sample.health.HealthCheckResource as a root resource class
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.example.appengine.helloworld.HelloResource as a root resource class
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.sample.exception.ConflictExceptionMapper as a provider class
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.sample.exception.IllegalArgumentExceptionMapper as a provider class
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering com.sample.webjars.JaxRsWebjarsServlet as a root resource class
Feb 24, 2017 10:05:19 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19.3 10/24/2016 03:43 PM'
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.sample.exception.ConflictExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.sample.exception.IllegalArgumentExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.sample.health.HealthCheckResource to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.example.appengine.helloworld.HelloResource to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding com.sample.webjars.JaxRsWebjarsServlet to GuiceManagedComponentProvider with the scope "Singleton"
Feb 24, 2017 10:05:19 PM com.google.apphosting.utils.jetty.JettyLogger info
INFO: Started SelectChannelConnector@localhost:54117
Feb 24, 2017 10:05:19 PM com.google.appengine.tools.development.AbstractModule startup
INFO: Module instance default is running at http://localhost:54117/
Feb 24, 2017 10:05:19 PM com.google.appengine.tools.development.AbstractModule startup
INFO: The admin console is running at http://localhost:54117/_ah/admin
Feb 24, 2017 3:05:55 PM com.google.appengine.tools.development.devappserver2.DevAppServer2Impl doStart
INFO: Dev App Server is now running

I've been chasing the problem down all week. I started with the helloworld-new-plugins sample project from Google (which worked). Then I gradually added on layers of my app until it stopped working.  Through trial and error I discovered that it works if some of the bindings are commented out.  There are four bindings for exception mappings. If only one of the exception mappers is bound, it works. Doesn't matter which one.  There is another binding for a resource class. If that is commented out, then I can bind any two of the exception mappers. None of the other bindings seem to have any effect. Keep in mind, this only happens on Windows-- all three developers who tried on Windows got the same problem, and but it works fine for both a Linux and a Mac developer.

The other symptom is that it takes about 2 minutes to startup when it's not working.  When it works, it takes about 10 seconds or less. I tried profiling using the IntelliJ profiler but couldn't get it to return results. I don't know if that's a configuration problem, a bug in IntelliJ, or my lack of experience running it.

When it fails, it never hits the GuiceFilter, which makes me wonder if maybe the problem isn't in the Java code, but somewhere else like in the python dev server. I tried updating to the latest Google Cloud SDK but it didn't fix the issue. I tried running the python commands directly, adding verbose output. It produced too much output to be very useful, almost all during the first 10 seconds or so. I tried bumping the Java logging level up but that didn't show anything either.

Has anyone seen anything remotely similar to this? Any ideas on where to go from here?

[Adam (Cloud Platform Support)]

We've seen this error occasionally but reproducing it has been hit or miss. I'd advise filing an issue on the googleappengine issue tracker and uploading a sample app which exhibits the problem. If you provide a link to the issue I will pick it up from there.

[Brian de Alwis]

In my experience, "bad runtime process port" usually indicates that something is writing to System.out.  It seems the dev_appserver communicates to the spawned JVMs via stdin/stdout, and so any other messages interfere.

Brian.

--
You received this message because you are subscribed to the Google Groups "Google App Engine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Visit this group at https://groups.google.com/group/google-appengine.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/90621c54-58da-44b4-af3c-7c71dac4d81c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Kevin Wise]

Ok, I'll trim down the project a bit and file an issue. Is there any workaround from what you've seen previously?

[Kevin Wise]

@Adam the issue has been created: https://code.google.com/p/googleappengine/issues/detail?id=13587
Let me know if you need anything else