Delay when starting Google Appengine devserver with Maven plugin on Mac OS X Mavericks

Question

Since updating to Mac OS X Mavericks, I experience some serious delay while starting the Google Appengine Devserver with the maven plugin. Here is a snippet from the logfile:

1: Okt 26, 2013 10:46:16 PM com.google.apphosting.utils.config.AppEngineWebXmlReader readAppEngineWebXml
2: INFO: Successfully processed /Users/Me/workspace/example/target/example-0.1-SNAPSHOT/WEB-INF/appengine-web.xml
3: [INFO] Running /Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home/jre/bin/java -XstartOnFirstThread -javaagent:/Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/agent/appengine-agent.jar -Xbootclasspath/p:/Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/override/appengine-dev-jdk-overrides.jar -Dappengine.fullscan.seconds=5 -classpath /Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/appengine-tools-api.jar com.google.appengine.tools.development.DevAppServerMain --allow_remote_shutdown -a 0.0.0.0 /Users/Me/workspace/example/target/example-0.1-SNAPSHOT
4: [INFO] objc[897]: Class JavaLaunchHelper is implemented in both /Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home/jre/bin/java and /Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home/jre/lib/libinstrument.dylib. One of the two will be used. Which one is undefined.
5: [INFO] Okt 26, 2013 10:47:34 PM com.google.apphosting.utils.config.AppEngineWebXmlReader readAppEngineWebXml

Compare the timestamps in line 1 and 5 of this example (the actual log is much longer, of course). The difference is 78 seconds! Almost all of this time is consumed in line 3.

Here, for better readability, I have once again line 3:

[INFO] Running /Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home/jre/bin/java -XstartOnFirstThread -javaagent:/Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/agent/appengine-agent.jar -Xbootclasspath/p:/Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/override/appengine-dev-jdk-overrides.jar -Dappengine.fullscan.seconds=5 -classpath /Users/Me/.m2/repository/com/google/appengine/appengine-java-sdk/1.8.6/appengine-java-sdk/appengine-java-sdk-1.8.6/lib/appengine-tools-api.jar com.google.appengine.tools.development.DevAppServerMain --allow_remote_shutdown -a 0.0.0.0 /Users/Me/workspace/example/target/example-0.1-SNAPSHOT

I guess, that line 4 has nothing to do with this issue, it is something different which should be fixed in 1.7.0u60.

Does anyone have a clue, what might be wrong here?

I suspected, that it had something to do with a WiFi issue, but even with disabled WiFi and on LAN (it's an "old" MacBook Pro with an Ethernet port), I experience the same issue.

[Edit] When I execute command in line 3 directly in the terminal, there is no delay. But with maven, there is a delay. I tried multiple times one and the other way…

Moritz Petersen · Accepted Answer · 2013-10-27T14:06:21.497

OK, I found the culprit. It's in the Appengine Maven Plugin class AbstractDevAppServerMojo.

The reason is, that - and that's new to me - the plugin first tries to stop a running development server. That's implemented in this method:

  protected void stopDevAppServer() throws MojoExecutionException {
    HttpURLConnection connection = null;
    try {
      Integer port = firstNonNull(this.port, 8080);
      URL url = new URL("http", firstNonNull(address, "localhost"), port, "/_ah/admin/quit");
      connection = (HttpURLConnection) url.openConnection();
      connection.setDoOutput(true);
      connection.setDoInput(true);
      connection.setRequestMethod("POST");
      connection.getOutputStream().write(0); // <-- Problem is here!
      ByteStreams.toByteArray(connection.getInputStream());
      connection.disconnect();
      getLog().warn("Shutting down devappserver on port " + port);
      Thread.sleep(2000);
    } catch (MalformedURLException e) {
      throw new MojoExecutionException("URL malformed attempting to stop the devserver : " + e.getMessage());
    } catch (IOException e) {
      getLog().debug("Was not able to contact the devappserver to shut it down.  Most likely this is due to it simply not running anymore. ", e);
    } catch (InterruptedException e) {
      Throwables.propagate(e);
    }
  }

The problem happens only, if the development server is not running. In that case, the URL does not exist and the HttpUrlConnection waits for a timeout.

A workaround is to change the connection timeout duration. For example, setting it to 1 second:

      connection.setRequestMethod("POST");
      connection.setConnectTimeout(1000);
      connection.getOutputStream().write(0);

This works for me and it should also work for others, since the development server usually runs on the same machine. It could also be implemented as a configuration parameter.

So, it has nothing to do with Mavericks (sorry for suspecting you, Apple), but with the Maven plugin itself. Or maybe the timeout duration has been changed somehow in Mavericks.

My solution to this issue? It happens only once, otherwise the development server runs and gets stopped by the plugin automatically. That's good enough for me now.

[Edit] Created an issue for the Maven plugin.

I know this is 1 year old, but can you tell me which goal you're running which causes the plugin to automatically stop a running server? When I run the `appengine:devserver` goal with an already-running server I get `bind failed: Address already in use` and it's still waiting for > 60s when starting. — tx802, Nov 19 '14 at 17:40
For anyone else with this problem, I found I can avoid it by either commenting out `
0.0.0.0
` or disabling my (OS X) firewall. — tx802, Apr 28 '15 at 14:24

Delay when starting Google Appengine devserver with Maven plugin on Mac OS X Mavericks

1 Answers1