0

I've got a Grails 2.4.3 app for internal use in my company. Problem is, after some time when I had it running (grails dev run-app), it terminates listening without prior notice:

INFO  [Thread-3]: Pausing ProtocolHandler ["http-bio-8080"]
INFO  [Thread-3]: Stopping service Tomcat
### Shutting down.
INFO  [Thread-3]: Stopping ProtocolHandler ["http-bio-8080"]
INFO  [Thread-3]: Destroying ProtocolHandler ["http-bio-8080"]

(The 3rd line is from the destroy() method in my BootStrap.groovy)

For datasource connections, there are keepalive strategies for pooled connections. I'd like the grails app to stay online, too.

How can I investigate on what causes the server to stop listening? Is this a common issue and can it be solved by config?

Edit:

The root logger shows the following on DEBUG level:

DEBUG [http-bio-8080-exec-4]: Counting down[http-bio-8080-exec-4] latch=2
DEBUG [http-bio-8080-exec-1]: Error parsing HTTP request header
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
...
DEBUG [http-bio-8080-exec-1]: Socket: [org.apache.tomcat.util.net.SocketWrapper@5c0b659a:Socket[addr=/0:0:0:0:0:0:0:1,port=58705,localport=8080]], Status in: [OPEN_READ], State out: [CLOSED]
DEBUG [http-bio-8080-exec-1]: Counting down[http-bio-8080-exec-1] latch=1
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: Start expire sessions StandardManager at 1421320212649 sessioncount 0
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: End expire sessions StandardManager processingTime 0 expired sessions: 0
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: Start expire sessions StandardManager at 1421320272661 sessioncount 0
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: End expire sessions StandardManager processingTime 0 expired sessions: 0
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: Start expire sessions StandardManager at 1421320332673 sessioncount 0
DEBUG [ContainerBackgroundProcessor[StandardEngine[Tomcat]]]: End expire sessions StandardManager processingTime 0 expired sessions: 0
DEBUG [http-bio-8080-Acceptor-0]: Counting up[http-bio-8080-Acceptor-0] latch=1
DEBUG [http-bio-8080-exec-6]: Error parsing HTTP request header
java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(SocketInputStream.java:196)
    at java.net.SocketInputStream.read(SocketInputStream.java:122)
    at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:519)
...
DEBUG [http-bio-8080-exec-6]: Socket: [org.apache.tomcat.util.net.SocketWrapper@674b5757:Socket[addr=/10.41.2.116,port=46215,localport=8080]], Status in: [OPEN_READ], State out: [CLOSED]
DEBUG [http-bio-8080-exec-6]: Counting down[http-bio-8080-exec-6] latch=1
DEBUG [Thread-3]: Setting state for [StandardServer[-1]] to [STOPPING_PREP]
DEBUG [Thread-3]: Setting state for [StandardServer[-1]] to [STOPPING]
DEBUG [Thread-3]: Setting state for [StandardService[Tomcat]] to [STOPPING_PREP]
INFO  [Thread-3]: Pausing ProtocolHandler ["http-bio-8080"]
DEBUG [Thread-3]: About to unlock socket for:localhost/127.0.0.1:8080
DEBUG [Thread-3]: Socket unlock completed for:localhost/127.0.0.1:8080
DEBUG [http-bio-8080-Acceptor-0]: Counting down[http-bio-8080-Acceptor-0] latch=0
INFO  [Thread-3]: Stopping service Tomcat
DEBUG [Thread-3]: Setting state for [StandardService[Tomcat]] to [STOPPING]
DEBUG [Thread-3]: Setting state for [StandardEngine[Tomcat]] to [STOPPING_PREP]
DEBUG [Thread-3]: Setting state for [StandardEngine[Tomcat]] to [STOPPING]
DEBUG [Thread-3]: Setting state for [Pipeline[StandardEngine[Tomcat]]] to [STOPPING_PREP]
DEBUG [Thread-3]: Setting state for [Pipeline[StandardEngine[Tomcat]]] to [STOPPING]
DEBUG [Thread-3]: Setting state for [org.apache.catalina.core.StandardEngineValve[Tomcat]] to [STOPPING_PREP]
DEBUG [Thread-3]: Setting state for [org.apache.catalina.core.StandardEngineValve[Tomcat]] to [STOPPING]
DEBUG [Thread-3]: Setting state for [org.apache.catalina.core.StandardEngineValve[Tomcat]] to [STOPPED]
DEBUG [Thread-3]: Setting state for [Pipeline[StandardEngine[Tomcat]]] to [STOPPED]
DEBUG [Tomcat-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost]] to [STOPPING_PREP]
DEBUG [Tomcat-startStop-2]: Unregister host [localhost] at domain [null] for connector [Connector[HTTP/1.1-8080]]
DEBUG [Tomcat-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost]] to [STOPPING]
DEBUG [Tomcat-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost]]] to [STOPPING_PREP]
DEBUG [Tomcat-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost]]] to [STOPPING]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.valves.ErrorReportValve[localhost]] to [STOPPING_PREP]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.valves.ErrorReportValve[localhost]] to [STOPPING]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.valves.ErrorReportValve[localhost]] to [STOPPED]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.core.StandardHostValve[localhost]] to [STOPPING_PREP]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.core.StandardHostValve[localhost]] to [STOPPING]
DEBUG [Tomcat-startStop-2]: Setting state for [org.apache.catalina.core.StandardHostValve[localhost]] to [STOPPED]
DEBUG [Tomcat-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost]]] to [STOPPED]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent]] to [STOPPING_PREP]
DEBUG [localhost-startStop-2]: Unregister Context [/workspent] for connector [Connector[HTTP/1.1-8080]]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent]] to [STOPPING]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]] to [STOPPING_PREP]
DEBUG [localhost-startStop-2]: Unregister Wrapper [grails-errorhandler] in Context [/workspent] for connector [Connector[HTTP/1.1-8080]]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]] to [STOPPING]
DEBUG [localhost-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]]] to [STOPPING_PREP]
DEBUG [localhost-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]]] to [STOPPING]
DEBUG [localhost-startStop-2]: Setting state for [org.apache.catalina.core.StandardWrapperValve[grails-errorhandler]] to [STOPPING_PREP]
DEBUG [localhost-startStop-2]: Setting state for [org.apache.catalina.core.StandardWrapperValve[grails-errorhandler]] to [STOPPING]
DEBUG [localhost-startStop-2]: Setting state for [org.apache.catalina.core.StandardWrapperValve[grails-errorhandler]] to [STOPPED]
DEBUG [localhost-startStop-2]: Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]]] to [STOPPED]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails-errorhandler]] to [STOPPED]
DEBUG [localhost-startStop-2]: Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[/workspent].StandardWrapper[grails]] to [STOPPING_PREP]
DEBUG [localhost-startStop-2]: Unregister Wrapper [grails] in Context [/workspent] for connector [Connector[HTTP/1.1-8080]]
INFO  [localhost-startStop-2]: ### Shutting down. Current time is 2015-01-15T12:12:39.009+01:00
INFO  [localhost-startStop-2]: Destroying Spring FrameworkServlet 'grails'
Community
  • 1
  • 1
observer
  • 2,925
  • 1
  • 19
  • 38
  • From my experience this is not a common issue. Can you try increasing the log verbosity by setting the root logger level to debug or even trace? See [the docs](http://grails.org/doc/latest/guide/conf.html#logging) for instructions. – Gregor Petrin Dec 16 '14 at 10:28
  • Did the JVM crash? Did it generate a `hs_err_pid` file? This link helped me understand the dump log contents: https://www.fullcontact.com/blog/java-runtime-memory-use/ – Salvador Valencia Dec 18 '14 at 19:24
  • Thanks for your advices so far, I'll look further into it after the season vacations ;) – observer Dec 21 '14 at 21:59
  • @SalvadorValencia From my understanding it cannot be a JVM crash as the application runs through the rest of the shutdown normally. – observer Jan 15 '15 at 11:45

1 Answers1

1

Take a look in your stacktrace.log file, probably some error will be there.
As the docs says:

When exceptions occur, there can be an awful lot of noise in the stacktrace from Java and Groovy internals. Grails filters these typically irrelevant details and restricts traces to non-core Grails/Groovy class packages.

When this happens, the full trace is always logged to the StackTrace logger, which by default writes its output to a file called stacktrace.log

If you don't know where is your file, you can configure it through log4j: http://grails.org/doc/latest/guide/conf.html

In your Config.groovy:

error stdout: "StackTrace"
log4j = {
    appenders {
        rollingFile name: "stacktrace", maxFileSize: 1024,
                    file: "/var/tmp/logs/myApp-stacktrace.log"
    }
}
Victor
  • 5,043
  • 3
  • 41
  • 55
  • Grails filters the stack traces so they are shorter, but the error itself would still be reported! – Gregor Petrin Dec 16 '14 at 10:30
  • Sometimes some errors don't appear in the grails output, this is why i said to you to see your `stacktrace.log` – Victor Dec 16 '14 at 10:35
  • Which exceptions appear in the output depends on the configured logger levels, but those same rules apply for `stacktrace.log`. The only difference is in the stack trace detail (full stack traces appear in `stacktrace.log`) but OP is not getting any errors at all! – Gregor Petrin Dec 16 '14 at 10:40
  • I was not able to reproduce the problem for some time now after the holidays, anyways I gave +1 for the hint regarding the log4j config. – observer Jan 14 '15 at 11:31
  • Being more patient, now I was able to extract the debug output as such a shutdown has happened again today. I added the log outputs. – observer Jan 15 '15 at 11:23