DropWizard is awesome! Thanks for such a productivity booster! Even so, I found a little gotcha to share...
DropWizard should automatically log exceptions to console without the user needing to manually insert try-catch-log boilerplate to every resource method. This would reduce plumbing and improve usability.
I have the following gcwizard.yml config file:
logging:
Settings for logging to stdout.
console:
# If true, write log statements to stdout.
enabled: true
# Do not display log statements below this threshold to stdout.
threshold: TRACE
… and there's a server resource with a simple method like so:
@get
@timed
@ExceptionMetered
public Saying sayHello(@QueryParam("name") Optional name) {
// try {
dumpMetrics();
return new Saying(counter.incrementAndGet(), String.format(template, name.or(defaultName)));
// } catch (Throwable e) {
// LOG.error(e, "gcwizard error in sayHello");
// throw new RuntimeException(e);
// }
}
When I call the service curl tells me that something failed, but it turns out the dropwizard service didn't log any stacktrace:
$ curl http://localhost:8080/gcwizard?name=foo
There was an error processing your request. It has been logged (ID 46b4c2d7ea57bef0).
DropWizard console output isn't very helpful to diagnose the problem:
…
INFO [2012-06-11 01:23:54,919] org.eclipse.jetty.server.AbstractConnector: Started [email protected]:8080
INFO [2012-06-11 01:23:54,923] org.eclipse.jetty.server.AbstractConnector: Started [email protected]:8081
0:0:0:0:0:0:0:1%0 - - [11/Jun/2012:01:23:57 +0000] "GET /gcwizard?name=foo HTTP/1.1" 400 72 2152 2152
Now, if I uncomment the try-catch-LOG block above and rerun I can see the stacktrace to diagnose the problem (see output further below). With this stacktrace I was easily able to fix my bug in calling some third party REST service (fix was to ask jackson to map JSON to Map.class instead of String.class). However, I believe I shouldn't have to manually add that try-catch-log boilerplate to every resource method since the doc at http://dropwizard.codahale.com/manual/core/#logging nicely promises to already do this:
"Error Handling :If your resource class unintentionally throws an exception, Dropwizard will log that exception (including stack traces) and return a terse, safe text/plain 500 Internal Server Error response."
What am I missing?
FYI, here is what my manual try-catch-log statement prints:
…
INFO [2012-06-11 01:22:54,639] org.eclipse.jetty.server.AbstractConnector: Started [email protected]:8080
INFO [2012-06-11 01:22:54,642] org.eclipse.jetty.server.AbstractConnector: Started [email protected]:8081
ERROR [2012-06-11 01:22:58,720] com.alpinefex.gcwizard.GCWizardResource: gcwizard error in sayHello
! javax.ws.rs.WebApplicationException: org.codehaus.jackson.map.JsonMappingException: Can not deserialize instance of java.lang.String out of START_OBJECT token
at [Source: com.sun.jersey.client.apache4.ApacheHttpClient4Handler$HttpClientResponseInputStream@3c9ed91f; line: 1, column: 1]
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.parseEntity(JacksonMessageBodyProvider.java:103)
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.readFrom(JacksonMessageBodyProvider.java:82)
! at com.sun.jersey.api.client.ClientResponse.getEntity(ClientResponse.java:554)
! at com.sun.jersey.api.client.ClientResponse.getEntity(ClientResponse.java:506)
! at com.sun.jersey.api.client.WebResource.handle(WebResource.java:684)
! at com.sun.jersey.api.client.WebResource.access$200(WebResource.java:74)
! at com.sun.jersey.api.client.WebResource$Builder.get(WebResource.java:507)
! at com.alpinefex.gcwizard.GCWizardResource.dumpMetrics(GCWizardResource.java:84)
! at com.alpinefex.gcwizard.GCWizardResource.sayHello(GCWizardResource.java:72)
! at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
! at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
! at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
! at java.lang.reflect.Method.invoke(Method.java:597)
! at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
! at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
! at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
! at com.yammer.metrics.jersey.InstrumentedResourceMethodDispatchProvider$TimedRequestDispatcher.dispatch(InstrumentedResourceMethodDispatchProvider.java:34)
! at com.yammer.metrics.jersey.InstrumentedResourceMethodDispatchProvider$ExceptionMeteredRequestDispatcher.dispatch(InstrumentedResourceMethodDispatchProvider.java:73)
! at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
! at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
! at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
! at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
! at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1483)
! at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1414)
! at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1363)
! at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1353)
! at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:414)
! at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
! at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:708)
! at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
! at com.yammer.dropwizard.jetty.NonblockingServletHolder.handle(NonblockingServletHolder.java:47)
! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1367)
! at com.yammer.dropwizard.servlets.ThreadNameFilter.doFilter(ThreadNameFilter.java:29)
! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1338)
! at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:484)
! at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1065)
! at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:413)
! at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:999)
! at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111)
! at com.yammer.metrics.jetty.InstrumentedHandler.handle(InstrumentedHandler.java:200)
! at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:270)
! at com.yammer.dropwizard.jetty.BiDiGzipHandler.handle(BiDiGzipHandler.java:123)
! at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149)
! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111)
! at org.eclipse.jetty.server.Server.handle(Server.java:350)
! at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:454)
! at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:47)
! at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:890)
! at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:944)
! at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:630)
! at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230)
! at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:66)
! at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293)
! at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:603)
! at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:538)
! at java.lang.Thread.run(Thread.java:680)
Caused by: ! org.codehaus.jackson.map.JsonMappingException: Can not deserialize instance of java.lang.String out of START_OBJECT token
at [Source: com.sun.jersey.client.apache4.ApacheHttpClient4Handler$HttpClientResponseInputStream@3c9ed91f; line: 1, column: 1]
! at org.codehaus.jackson.map.JsonMappingException.from(JsonMappingException.java:163)
! at org.codehaus.jackson.map.deser.StdDeserializationContext.mappingException(StdDeserializationContext.java:219)
! at org.codehaus.jackson.map.deser.std.StringDeserializer.deserialize(StringDeserializer.java:44)
! at org.codehaus.jackson.map.deser.std.StringDeserializer.deserialize(StringDeserializer.java:13)
! at org.codehaus.jackson.map.ObjectMapper._readMapAndClose(ObjectMapper.java:2732)
! at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1923)
! at com.yammer.dropwizard.json.Json.readValue(Json.java:335)
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.parseEntity(JacksonMessageBodyProvider.java:101)
!... 56 common frames omitted
ERROR [2012-06-11 01:22:58,722] com.yammer.dropwizard.jersey.LoggingExceptionMapper: Error handling a request: 46b4c2d7ea57bef0
! java.lang.RuntimeException: javax.ws.rs.WebApplicationException: org.codehaus.jackson.map.JsonMappingException: Can not deserialize instance of java.lang.String out of START_OBJECT token
at [Source: com.sun.jersey.client.apache4.ApacheHttpClient4Handler$HttpClientResponseInputStream@3c9ed91f; line: 1, column: 1]
! at com.alpinefex.gcwizard.GCWizardResource.sayHello(GCWizardResource.java:76)
! at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
! at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
! at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
! at java.lang.reflect.Method.invoke(Method.java:597)
! at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
! at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
! at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
! at com.yammer.metrics.jersey.InstrumentedResourceMethodDispatchProvider$TimedRequestDispatcher.dispatch(InstrumentedResourceMethodDispatchProvider.java:34)
! at com.yammer.metrics.jersey.InstrumentedResourceMethodDispatchProvider$ExceptionMeteredRequestDispatcher.dispatch(InstrumentedResourceMethodDispatchProvider.java:73)
! at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
! at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
! at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
! at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
! at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1483)
! at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1414)
! at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1363)
! at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1353)
! at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:414)
! at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
! at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:708)
! at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
! at com.yammer.dropwizard.jetty.NonblockingServletHolder.handle(NonblockingServletHolder.java:47)
! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1367)
! at com.yammer.dropwizard.servlets.ThreadNameFilter.doFilter(ThreadNameFilter.java:29)
! at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1338)
! at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:484)
! at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1065)
! at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:413)
! at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:999)
! at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111)
! at com.yammer.metrics.jetty.InstrumentedHandler.handle(InstrumentedHandler.java:200)
! at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:270)
! at com.yammer.dropwizard.jetty.BiDiGzipHandler.handle(BiDiGzipHandler.java:123)
! at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149)
! at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111)
! at org.eclipse.jetty.server.Server.handle(Server.java:350)
! at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:454)
! at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:47)
! at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:890)
! at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:944)
! at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:630)
! at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230)
! at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:66)
! at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293)
! at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:603)
! at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:538)
! at java.lang.Thread.run(Thread.java:680)
Caused by: ! javax.ws.rs.WebApplicationException: org.codehaus.jackson.map.JsonMappingException: Can not deserialize instance of java.lang.String out of START_OBJECT token
at [Source: com.sun.jersey.client.apache4.ApacheHttpClient4Handler$HttpClientResponseInputStream@3c9ed91f; line: 1, column: 1]
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.parseEntity(JacksonMessageBodyProvider.java:103)
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.readFrom(JacksonMessageBodyProvider.java:82)
! at com.sun.jersey.api.client.ClientResponse.getEntity(ClientResponse.java:554)
! at com.sun.jersey.api.client.ClientResponse.getEntity(ClientResponse.java:506)
! at com.sun.jersey.api.client.WebResource.handle(WebResource.java:684)
! at com.sun.jersey.api.client.WebResource.access$200(WebResource.java:74)
! at com.sun.jersey.api.client.WebResource$Builder.get(WebResource.java:507)
! at com.alpinefex.gcwizard.GCWizardResource.dumpMetrics(GCWizardResource.java:84)
! at com.alpinefex.gcwizard.GCWizardResource.sayHello(GCWizardResource.java:72)
!... 48 common frames omitted
Caused by: ! org.codehaus.jackson.map.JsonMappingException: Can not deserialize instance of java.lang.String out of START_OBJECT token
at [Source: com.sun.jersey.client.apache4.ApacheHttpClient4Handler$HttpClientResponseInputStream@3c9ed91f; line: 1, column: 1]
! at org.codehaus.jackson.map.JsonMappingException.from(JsonMappingException.java:163)
! at org.codehaus.jackson.map.deser.StdDeserializationContext.mappingException(StdDeserializationContext.java:219)
! at org.codehaus.jackson.map.deser.std.StringDeserializer.deserialize(StringDeserializer.java:44)
! at org.codehaus.jackson.map.deser.std.StringDeserializer.deserialize(StringDeserializer.java:13)
! at org.codehaus.jackson.map.ObjectMapper._readMapAndClose(ObjectMapper.java:2732)
! at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1923)
! at com.yammer.dropwizard.json.Json.readValue(Json.java:335)
! at com.yammer.dropwizard.jersey.JacksonMessageBodyProvider.parseEntity(JacksonMessageBodyProvider.java:101)
!... 56 common frames omitted
0:0:0:0:0:0:0:1%0 - - [11/Jun/2012:01:22:56 +0000] "GET /gcwizard?name=foo HTTP/1.1" 500 86 2587 2587