GoogleCloudPlatform / gcloud-maven-plugin

Cloud SDK Maven Plugin for Google App Engine (Managed VMs and non Managed VMs)
Apache License 2.0
29 stars 24 forks source link

run_start goal does not complete #20

Closed jboynes closed 9 years ago

jboynes commented 9 years ago

I'm trying to use the plugin to run an integration test on my application using the following configuration:

      <plugin>
        <groupId>com.google.appengine</groupId>
        <artifactId>gcloud-maven-plugin</artifactId>
        <version>0.9.64.v20150610</version>
        <executions>
          <execution>
            <id>gcloud-start</id>
            <phase>pre-integration-test</phase>
            <goals>
              <goal>run_start</goal>
            </goals>
          </execution>
          <execution>
            <id>gcloud-stop</id>
            <phase>post-integration-test</phase>
            <goals>
              <goal>run_stop</goal>
            </goals>
          </execution>
        </executions>
      </plugin>

The run_start goal does not complete so my tests do not run. The dev server is started and I can curl the application from a separate window but the build just hangs like it is waiting for something. The last info in the log was:

[INFO] Exception in thread Thread-2:
[INFO] Traceback (most recent call last):
[INFO]   File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 810, in __bootstrap_inner
[INFO]     self.run()
[INFO]   File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 763, in run
[INFO]     self.__target(*self.__args, **self.__kwargs)
[INFO]   File "/Users/jeremy/google-cloud-sdk/platform/google_appengine/google/appengine/tools/docker/containers.py", line 643, in _ListenToLogs
[INFO]     for line in log_lines:
[INFO]   File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 225, in _multiplexed_response_stream_helper
[INFO]     socket = self._get_raw_response_socket(response)
[INFO]   File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 167, in _get_raw_response_socket
[INFO]     self._raise_for_status(response)
[INFO]   File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 119, in _raise_for_status
[INFO]     raise errors.APIError(e, response, explanation=explanation)
[INFO] APIError: 500 Server Error: Internal Server Error ("http: Hijack is incompatible with use of CloseNotifier")
[INFO] 
[INFO] INFO     2015-06-19 15:28:13,254 module.py:1692] New instance for module "default" serving on:
[INFO] http://localhost:8080
[INFO] 
[INFO] INFO     2015-06-19 15:28:13,737 module.py:737] default: "GET /_ah/start HTTP/1.1" 404 1012
[INFO] INFO     2015-06-19 15:28:13,737 health_check_service.py:101] Health checks starting for instance 0.
[INFO] WARNING  2015-06-19 15:28:22,324 containers.py:489] Image Id 38956ca1862f:latest cannot be removed: 404 Client Error: Not Found ("No such image: 38956ca1862f:latest").
[INFO] Try cleaning up old images manually.
[INFO] They can be listed with "docker images".
ludoch commented 9 years ago

Can you try to do a jstat on the maven process? Maybe be (or not) related to the warning?

On Fri, Jun 19, 2015 at 8:41 AM, Jeremy Boynes notifications@github.com wrote:

I'm trying to use the plugin to run an integration test on my application using the following configuration:

  <plugin>
    <groupId>com.google.appengine</groupId>
    <artifactId>gcloud-maven-plugin</artifactId>
    <version>0.9.64.v20150610</version>
    <executions>
      <execution>
        <id>gcloud-start</id>
        <phase>pre-integration-test</phase>
        <goals>
          <goal>run_start</goal>
        </goals>
      </execution>
      <execution>
        <id>gcloud-stop</id>
        <phase>post-integration-test</phase>
        <goals>
          <goal>run_stop</goal>
        </goals>
      </execution>
    </executions>
  </plugin>

The run_start goal does not complete so my tests do not run. The dev server is started and I can curl the application from a separate window but the build just hangs like it is waiting for something. The last info in the log was:

[INFO] Exception in thread Thread-2: [INFO] Traceback (most recent call last): [INFO] File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 810, in bootstrap_inner [INFO] self.run() [INFO] File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 763, in run [INFO] self.__target(_self.args, *_self.__kwargs) [INFO] File "/Users/jeremy/google-cloud-sdk/platform/google_appengine/google/appengine/tools/docker/containers.py", line 643, in _ListenToLogs [INFO] for line in log_lines: [INFO] File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 225, in _multiplexed_response_stream_helper [INFO] socket = self._get_raw_response_socket(response) [INFO] File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 167, in _get_raw_response_socket [INFO] self._raise_for_status(response) [INFO] File "/Users/jeremy/google-cloud-sdk/lib/docker/docker/client.py", line 119, in _raise_for_status [INFO] raise errors.APIError(e, response, explanation=explanation) [INFO] APIError: 500 Server Error: Internal Server Error ("http: Hijack is incompatible with use of CloseNotifier") [INFO] [INFO] INFO 2015-06-19 15:28:13,254 module.py:1692] New instance for module "default" serving on: [INFO] http://localhost:8080 [INFO] [INFO] INFO 2015-06-19 15:28:13,737 module.py:737] default: "GET /_ah/start HTTP/1.1" 404 1012 [INFO] INFO 2015-06-19 15:28:13,737 health_check_service.py:101] Health checks starting for instance 0. [INFO] WARNING 2015-06-19 15:28:22,324 containers.py:489] Image Id 38956ca1862f:latest cannot be removed: 404 Client Error: Not Found ("No such image: 38956ca1862f:latest"). [INFO] Try cleaning up old images manually. [INFO] They can be listed with "docker images".

— Reply to this email directly or view it on GitHub https://github.com/GoogleCloudPlatform/gcloud-maven-plugin/issues/20.

jboynes commented 9 years ago

Assuming you mean jstack. Looks like the main thread is just waiting for something. Looking at what decrements the latch I see it's parsing the output looking for health check messages but I don't see any lines like that on the console.

2015-06-22 07:58:36
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.31-b07 mixed mode):

"Attach Listener" #14 daemon prio=9 os_prio=31 tid=0x00007fde688cc800 nid=0x380f waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"standard-out-redirection-devappserver" #12 daemon prio=5 os_prio=31 tid=0x00007fde660bf800 nid=0x5703 runnable [0x0000000129623000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    - locked <0x0000000744499770> (a java.lang.UNIXProcess$ProcessPipeInputStream)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x00000007444a1be8> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.Reader.read(Reader.java:100)
    at java.util.Scanner.readInput(Scanner.java:804)
    at java.util.Scanner.findWithinHorizon(Scanner.java:1685)
    at java.util.Scanner.hasNextLine(Scanner.java:1500)
    at com.google.appengine.gcloudapp.AbstractGcloudMojo$1.run(AbstractGcloudMojo.java:327)

"process reaper" #11 daemon prio=10 os_prio=31 tid=0x00007fde66900800 nid=0x5503 runnable [0x0000000127300000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.UNIXProcess.waitForProcessExit(Native Method)
    at java.lang.UNIXProcess.access$500(UNIXProcess.java:55)
    at java.lang.UNIXProcess$4.run(UNIXProcess.java:226)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007fde64068000 nid=0x5103 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007fde63803800 nid=0x4f03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fde63803000 nid=0x4d03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fde64055000 nid=0x4b03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fde64053800 nid=0x4903 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fde64024000 nid=0x3917 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fde63066000 nid=0x3503 in Object.wait() [0x00000001244d6000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
    - locked <0x0000000640010328> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fde63065800 nid=0x3303 in Object.wait() [0x00000001243d3000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x0000000640017a90> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=31 tid=0x00007fde64003000 nid=0x1303 waiting on condition [0x0000000103e1e000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000074449dec8> (a java.util.concurrent.CountDownLatch$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
    at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
    at com.google.appengine.gcloudapp.AbstractGcloudMojo.startCommand(AbstractGcloudMojo.java:376)
    at com.google.appengine.gcloudapp.GcloudAppAsyncStart.execute(GcloudAppAsyncStart.java:44)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:862)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:286)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:197)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

"VM Thread" os_prio=31 tid=0x00007fde63062800 nid=0x3103 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fde6400e800 nid=0x2103 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fde6400f800 nid=0x2303 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fde63802000 nid=0x2503 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fde63012800 nid=0x2703 runnable 

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fde63013000 nid=0x2903 runnable 

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fde63013800 nid=0x2b03 runnable 

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fde63014800 nid=0x2d03 runnable 

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fde63015000 nid=0x2f03 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007fde64069000 nid=0x5303 waiting on condition 

JNI global references: 251
jboynes commented 9 years ago

When I run curl I see:

$ curl -v http://localhost:8080/_ah/health?IsLastSuccessful=yes
* Hostname was NOT found in DNS cache
*   Trying ::1...
* Connected to localhost (::1) port 8080 (#0)
> GET /_ah/health?IsLastSuccessful=yes HTTP/1.1
> User-Agent: curl/7.37.1
> Host: localhost:8080
> Accept: */*
> 
< HTTP/1.1 200 OK
< content-type: text/plain
< Cache-Control: no-cache
< Expires: Fri, 01 Jan 1990 00:00:00 GMT
< Content-Length: 2
* Server Development/2.0 is not blacklisted
< Server: Development/2.0
< Date: Mon, 22 Jun 2015 15:07:18 GMT
< 
* Connection #0 to host localhost left intact
OK

but there's no line logged to the console output from the plugin (where I do see a log entry if I curl /)

ludoch commented 9 years ago

Fixed in July