How to configure JDK logging for Jersey 2 tests

Jersey uses JDK Logging API to log messages.

One way how to configure JDK Logging is a properties file. In such case you have to set JVM system property java.util.logging.config.file to reference the properties file.

Initially the logging configuration file logging.properties can look:

#All attributes details
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.SimpleFormatter.format=%4$-7s [%3$s] %5$s%6$s%n

#All log level details
.level=INFO
org.glassfish.jersey.level=CONFIG
org.glassfish.jersey.tracing.level=FINEST

The configuration explained:

• handlers=java.util.logging.ConsoleHandler - log messages are written to System.err
• java.util.logging.ConsoleHandler.level=FINEST - allow to log FINEST message;
  default is INFO so more detailed messages are suppressed by default
• java.util.logging.SimpleFormatter.format - example of simple and single line format - just level, logger name and message;
  Note: It just works with Java 7.
• org.glassfish.jersey.level=CONFIG - example of per-package level configuration;
  log all SEVERE, WARNING, INFO and CONFIG level Jersey messages
• org.glassfish.jersey.tracing.level=FINEST - example of detailed level configuration of specified package

And as mentioned it is necessary to set system property java.util.logging.config.file. Do you want to see log messages during unit testing (e.g. using maven)? There are two options:

• run tests in new JVM instance (fork option) and configure the system property in such maven plugin
• enhance maven command line parameter and add the
  -Djava.util.logging.config.file=... property

For example, run test application using Jetty server for test module tracing-support:

~/jersey2/tests/integration/tracing-support$ mvn compile jetty:run -Djava.util.logging.config.file=src/test/resources/logging.properties

-that's all folks

Jersey 2 - Tracing support

What is Jersey?

This is my first Jersey related post so let me introduce Jersey framework.

Jersey RESTful Web Services framework is open source, production quality, framework for developing RESTful Web Services in Java that provides support for JAX-RS APIs and serves as a JAX-RS (JSR 311 & JSR 339) Reference Implementation.

Jersey framework is more than the JAX-RS Reference Implementation. Jersey provides it’s own API that extend the JAX-RS toolkit with additional features and utilities to further simplify RESTful service and client development. Jersey also exposes numerous extension SPIs so that developers may extend Jersey to best suit their needs.

Today I would like to introduce Tracing support feature that is part of Jersey 2 since 2.3 release. Current version of writing this blog post is 2.4.1.

Tracing Support

Jersey can provide tracing or diagnostic information about server-side processing of individual requests. This facility may provide vital information when troubleshooting your misbehaving Jersey or JAX-RS application. When enabled, Jersey tracing facility collects useful information from all parts of JAX-RS server-side request processing pipeline: PreMatchRequestFilter, ResourceMatching, RequestFilter, ReadIntercept, MBR, Invoke, ResponseFilter, WriteIntercept, MBW, as well as ExceptionHandling.

The collected tracing information related to a single request is returned to the requesting client in the HTTP headers of a response for the request. The information is also logged on the server-side using a dedicated Java Logger instance.

Configuration options

Tracing support is disabled by default. You can enable it either "globally" for all application requests or selectively per request. The tracing support activation is controlled by setting the jersey.config.server.tracing application configuration property (ServerProperties.TRACING). The property value is expected to be one of the following:

• OFF - tracing support is disabled (default value).
• ON_DEMAND - tracing support is in a stand-by mode; it is enabled selectively per request, via a special X-Jersey-Tracing-Accept HTTP request header.
• ALL - tracing support is enabled for all request.

The level of detail of the information provided by Jersey tracing facility - the tracing threshold - can be customized. The tracing threshold can be set at the application level via jersey.config.server.tracing.threshold application configuration property (ServerProperties.TRACING_THRESHOLD), or at a request level, via X-Jersey-Tracing-Threshold HTTP request header. The request level configuration overrides any application level setting. There are 3 supported levels of detail for Jersey tracing:

• SUMMARY - very basic summary information about the main request processing stages.
• TRACE - detailed information about activities in all the main request processing stages (default threshold value).
• VERBOSE - most verbose mode that provides extended information similar to TRACE level, however with details on entity providers (MBR/MBW) that were skipped during the provider selection phase for any reason (lower priority, pattern matching, etc). Additionally, in this mode all received request headers are echoed as part of the tracing information.

Both properties accept String value only.

Tracing Log

As mentioned earlier, all tracing information is also logged using a dedicated Java Logger at server-side. The individual tracing messages are logged immediately as the tracing events occur. The default name of the tracing logger is prefixed org.glassfish.jersey.tracing. with a default suffix general. This logger name can be customized per request by including a X-Jersey-Tracing-Logger HTTP request header as will be shown later.

Configuring tracing support via HTTP request headers

Whenever the tracing support is active (ON_DEMAND or ALL) you can customize the tracing behaviour by including one or more of the following request HTTP headers in your individual requests:

• X-Jersey-Tracing-Accept - used to enable the tracing support for the particular request. It is applied only when the application-level tracing support is configured to ON_DEMAND mode. The value of the header is not used by the Jersey tracing facility and as such it can be any arbitrary (even empty) string.
• X-Jersey-Tracing-Threshold - used to override the tracing level of detail. Allowed values are: SUMMARY, TRACE, VERBOSE.
• X-Jersey-Tracing-Logger - used to override the tracing Java logger name suffix.

Format of the HTTP response headers

At the end of request processing all tracing messages are appended to the HTTP response as individual headers named X-Jersey-Tracing-nnn where nnn is index number of message starting at 0.

Each tracing message is in the following format: CATEGORY [TIME] TEXT, e.g.

X-Jersey-Tracing-007: WI          [85.95 / 183.69 ms | 46.77 %] WriteTo summary: 4 interceptors

The CATEGORY is used to categorize tracing events according to the following event types:

• START - start of request processing information
• PRE-MATCH - pre-matching request filter processing
• MATCH - matching request URI to a resource method
• REQ-FILTER - request filter processing
• RI - entity reader interceptor processing
• MBR - message body reader selection and invocation
• INVOKE - resource method invocation
• RESP-FILTER - response filter processing
• WI - write interceptor processing
• MBW - message body writer selection and invocation
• MVC - template engine integration
• EXCEPTION - exception mapping
• FINISHED - processing finish summary

The TIME, if present, is a composite value that consists of 3 parts [ duration / time_from_start | total_req_ratio ]:

1. duration - the duration of the current trace event [milliseconds]; e.g. duration of filter processing
2. time_from_start - the end time of the current event with respect to the request processing start time [milliseconds]
3. total_req_ratio - the duration of the current event with respect to the total request processing time [percentage]; this value tells you how significant part of the whole request processing time has been spent in the processing phase described by the current event

There are certain tracing events that do not have any duration. In such case, duration values are not set (---- literal).

The tracing event TEXT is a free-form detailed text information about the current diagnostic event.

For better identification, instances of JAX-RS components are represented by class name, identity hash code and @Priority value if set, example of filter instance with priority 5001: [org.glassfish.jersey.tests.integration.tracing.ContainerResponseFilter5001 @494a8227 #5001].

Tracing Examples

Threshold header, SUMMARY level example

Example of SUMMARY level messages from tests/integration/tracing-support module. Test application returns tracing headers for every request (AllTracingSupport.java, TracingSupport.java).

Run test application using Jetty server:

~/jersey2/tests/integration/tracing-support$ mvn compile jetty:run

Let's trace POST request with SUMMARY level using "Threshold" header (replacing default TRACE level):

$ curl -i http://localhost:9998/ALL/root/sub-resource-locator/sub-resource-method -H content-type:application/x-jersey-test --data '-=#[LKR]#=-' -H X-Jersey-Tracing-Threshold:SUMMARY -H accept:application/x-jersey-test -X POST

X-Jersey-Tracing-000: START       [ ---- /  ---- ms |  ---- %] baseUri=[http://localhost:9998/ALL/] requestUri=[http://localhost:9998/ALL/root/sub-resource-locator/sub-resource-method] method=[POST] authScheme=[n/a] accept=[application/x-jersey-test] accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=[application/x-jersey-test] content-length=[11]
X-Jersey-Tracing-001: PRE-MATCH   [ 0.01 /  0.68 ms |  0.01 %] PreMatchRequest summary: 2 filters
X-Jersey-Tracing-002: MATCH       [ 8.44 /  9.15 ms |  4.59 %] RequestMatching summary
X-Jersey-Tracing-003: REQ-FILTER  [ 0.01 /  9.20 ms |  0.00 %] Request summary: 2 filters
X-Jersey-Tracing-004: RI          [86.14 / 95.49 ms | 46.87 %] ReadFrom summary: 3 interceptors
X-Jersey-Tracing-005: INVOKE      [ 0.04 / 95.70 ms |  0.02 %] Resource [org.glassfish.jersey.tests.integration.tracing.SubResource @901a4f3] method=[public org.glassfish.jersey.tests.integration.tracing.Message org.glassfish.jersey.tests.integration.tracing.SubResource.postSub(org.glassfish.jersey.tests.integration.tracing.Message)]
X-Jersey-Tracing-006: RESP-FILTER [ 0.01 / 96.55 ms |  0.00 %] Response summary: 2 filters
X-Jersey-Tracing-007: WI          [85.95 / 183.69 ms | 46.77 %] WriteTo summary: 4 interceptors
X-Jersey-Tracing-008: FINISHED    [ ---- / 183.79 ms |  ---- %] Response status: 200/SUCCESSFUL|OK

Accept header, MVC integration, TRACE level example

Second example shows MVC message (from jersey-mvc-jsp integration module) using examples/bookstore-webapp module.

Run test application using Jetty server:

~/jersey2/examples/bookstore-webapp$ mvn compile jetty:run

Let's trace GET request using "Accept" header to activate on-demand tracing support messages (MyApplication.java). This is just snippet of default TRACE level messages to demonstrate MVC JSP forwarding message:

$ curl -i http://localhost:9998/items/3/tracks/0 -H X-Jersey-Tracing-Accept:whatever

...
X-Jersey-Tracing-033: WI          [ 0.00 / 23.39 ms |  0.02 %] [org.glassfish.jersey.server.mvc.internal.TemplateMethodInterceptor @141bcd49 #4000] BEFORE context.proceed()
X-Jersey-Tracing-034: WI          [ 0.01 / 23.42 ms |  0.02 %] [org.glassfish.jersey.filter.LoggingFilter @2d427def #-2147483648] BEFORE context.proceed()
X-Jersey-Tracing-035: MBW         [ ---- / 23.45 ms |  ---- %] Find MBW for type=[org.glassfish.jersey.server.mvc.internal.ImplicitViewable] genericType=[org.glassfish.jersey.server.mvc.internal.ImplicitViewable] mediaType=[[javax.ws.rs.core.MediaType @7bfbfeae]] annotations=[]
X-Jersey-Tracing-036: MBW         [ ---- / 23.52 ms |  ---- %] [org.glassfish.jersey.server.mvc.internal.ViewableMessageBodyWriter @78b353d4] IS writeable
X-Jersey-Tracing-037: MVC         [ ---- / 24.05 ms |  ---- %] Forwarding view to JSP page [/org/glassfish/jersey/examples/bookstore/webapp/resource/Track/index.jsp], model [org.glassfish.jersey.examples.bookstore.webapp.resource.Track @3937f594]
X-Jersey-Tracing-038: MBW         [ 1.09 / 24.63 ms |  4.39 %] WriteTo by [org.glassfish.jersey.server.mvc.internal.ViewableMessageBodyWriter @78b353d4]
X-Jersey-Tracing-039: WI          [ 0.00 / 24.67 ms |  0.01 %] [org.glassfish.jersey.filter.LoggingFilter @2d427def #-2147483648] AFTER context.proceed()
X-Jersey-Tracing-040: WI          [ 0.00 / 24.70 ms |  0.01 %] [org.glassfish.jersey.server.mvc.internal.TemplateMethodInterceptor @141bcd49 #4000] AFTER context.proceed()
...

Logger header, VERBOSE level example

The last example shows JDK logger name configuration and also uses  tests/integration/tracing-support module.

Run test application using Jetty server with JDK logger config file set (JDK logging configuration from file works just on Java 7):

~/jersey2/tests/integration/tracing-support$ mvn compile jetty:run -Djava.util.logging.config.file=src/test/resources/logging.properties

Let's trace POST request with VERBOSE level using "Threshold" header and customize server-side logger name (suffix "lkr") using "Logger" header:

$ curl -i http://localhost:9998/ALL/root/sub-resource-locator/sub-resource-method -H content-type:application/x-jersey-test --data '-=#[LKR]#=-' -H X-Jersey-Tracing-Threshold:VERBOSE -H X-Jersey-Tracing-Logger:lkr -H accept:application/x-jersey-test -X POST

Snippet of response Tracing headers, see "skipped" messages available just with VERBOSE level:

X-Jersey-Tracing-055: WI          [ 0.01 / 110.41 ms |  0.00 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @25f3027c #10] BEFORE context.proceed()
X-Jersey-Tracing-056: WI          [43.14 / 153.76 ms | 21.66 %] [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor39 @19378d8d #39] BEFORE context.proceed()
X-Jersey-Tracing-057: WI          [ 0.02 / 154.15 ms |  0.01 %] [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor45 @e2e30ea #45] BEFORE context.proceed()
X-Jersey-Tracing-058: WI          [ 0.01 / 154.49 ms |  0.01 %] [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @7a8d59eb #3000] BEFORE context.proceed()
X-Jersey-Tracing-059: MBW         [ ---- / 154.72 ms |  ---- %] Find MBW for type=[org.glassfish.jersey.tests.integration.tracing.Message] genericType=[org.glassfish.jersey.tests.integration.tracing.Message] mediaType=[[org.glassfish.jersey.message.internal.AcceptableMediaType @77d470a6]] annotations=[@javax.ws.rs.Path(value=sub-resource-method), @javax.ws.rs.POST()]
X-Jersey-Tracing-060: MBW         [ ---- / 154.95 ms |  ---- %] [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterTestFormat @2b40fbd9] IS writeable
X-Jersey-Tracing-061: MBW         [ ---- / 155.14 ms |  ---- %] [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterGeneric @375679be] is skipped
X-Jersey-Tracing-062: MBW         [ ---- / 155.28 ms |  ---- %] [org.glassfish.jersey.message.internal.XmlCollectionJaxbProvider$General @4e0919d8] is skipped
X-Jersey-Tracing-063: MBW         [ ---- / 155.42 ms |  ---- %] [org.glassfish.jersey.message.internal.XmlRootElementJaxbProvider$General @683ca3a4] is skipped
X-Jersey-Tracing-064: MBW         [ 0.03 / 155.58 ms |  0.01 %] WriteTo by [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterTestFormat @2b40fbd9]
X-Jersey-Tracing-065: WI          [ 0.00 / 155.77 ms |  0.00 %] [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @7a8d59eb #3000] AFTER context.proceed()
X-Jersey-Tracing-066: WI          [42.11 / 198.10 ms | 21.15 %] [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor45 @e2e30ea #45] AFTER context.proceed()
X-Jersey-Tracing-067: WI          [ 0.01 / 198.48 ms |  0.01 %] [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor39 @19378d8d #39] AFTER context.proceed()
X-Jersey-Tracing-068: WI          [ 0.00 / 198.72 ms |  0.00 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @25f3027c #10] AFTER context.proceed()
X-Jersey-Tracing-069: WI          [88.53 / 198.93 ms | 44.46 %] WriteTo summary: 4 interceptors

And same messages written to server-side log (customized logger name):

FINER   [org.glassfish.jersey.tracing.lkr] WI_BEFORE [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @25f3027c #10] BEFORE context.proceed() [ 0.01 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_BEFORE [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor39 @19378d8d #39] BEFORE context.proceed() [43.14 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_BEFORE [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor45 @e2e30ea #45] BEFORE context.proceed() [ 0.02 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_BEFORE [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @7a8d59eb #3000] BEFORE context.proceed() [ 0.01 ms]
FINER   [org.glassfish.jersey.tracing.lkr] MBW_FIND Find MBW for type=[org.glassfish.jersey.tests.integration.tracing.Message] genericType=[org.glassfish.jersey.tests.integration.tracing.Message] mediaType=[[org.glassfish.jersey.message.internal.AcceptableMediaType @77d470a6]] annotations=[@javax.ws.rs.Path(value=sub-resource-method), @javax.ws.rs.POST()] [ ---- ms]
FINER   [org.glassfish.jersey.tracing.lkr] MBW_SELECTED [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterTestFormat @2b40fbd9] IS writeable [ ---- ms]
FINEST  [org.glassfish.jersey.tracing.lkr] MBW_SKIPPED [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterGeneric @375679be] is skipped [ ---- ms]
FINEST  [org.glassfish.jersey.tracing.lkr] MBW_SKIPPED [org.glassfish.jersey.message.internal.XmlCollectionJaxbProvider$General @4e0919d8] is skipped [ ---- ms]
FINEST  [org.glassfish.jersey.tracing.lkr] MBW_SKIPPED [org.glassfish.jersey.message.internal.XmlRootElementJaxbProvider$General @683ca3a4] is skipped [ ---- ms]
FINER   [org.glassfish.jersey.tracing.lkr] MBW_WRITE_TO WriteTo by [org.glassfish.jersey.tests.integration.tracing.MessageBodyWriterTestFormat @2b40fbd9] [ 0.03 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_AFTER [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @7a8d59eb #3000] AFTER context.proceed() [ 0.00 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_AFTER [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor45 @e2e30ea #45] AFTER context.proceed() [42.11 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_AFTER [org.glassfish.jersey.tests.integration.tracing.WriterInterceptor39 @19378d8d #39] AFTER context.proceed() [ 0.01 ms]
FINER   [org.glassfish.jersey.tracing.lkr] WI_AFTER [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @25f3027c #10] AFTER context.proceed() [ 0.00 ms]
FINE    [org.glassfish.jersey.tracing.lkr] WI_SUMMARY WriteTo summary: 4 interceptors [88.53 ms]

You can see some differences. There is just duration value (if applicable), no time_from_start or total_req_ratio.

Message tracing level is transformed to JDK logging level:

• SUMMARY -> FINE
• TRACE   -> FINER
• VERBOSE -> FINEST

Each message type has unique ID transformed to message category while formatting HTTP response headers:

• START                   -> START
• START_HEADERS           -> START
• PRE_MATCH               -> PRE-MATCH
• PRE_MATCH_SUMMARY       -> PRE-MATCH
• MATCH_PATH_FIND         -> MATCH
• MATCH_PATH_NOT_MATCHED  -> MATCH
• MATCH_PATH_SELECTED     -> MATCH
• MATCH_PATH_SKIPPED      -> MATCH
• MATCH_LOCATOR           -> MATCH
• MATCH_RESOURCE_METHOD   -> MATCH
• MATCH_RUNTIME_RESOURCE  -> MATCH
• MATCH_RESOURCE          -> MATCH
• MATCH_SUMMARY           -> MATCH
• REQUEST_FILTER          -> REQ-FILTER
• REQUEST_FILTER_SUMMARY  -> REQ-FILTER
• METHOD_INVOKE           -> INVOKE
• DISPATCH_RESPONSE       -> INVOKE
• RESPONSE_FILTER         -> RESP-FILTER
• RESPONSE_FILTER_SUMMARY -> RESP-FILTER
• FINISHED                -> FINISHED
• EXCEPTION_MAPPING       -> EXCEPTION
• RI_BEFORE               -> RI
• RI_AFTER                -> RI
• RI_SUMMARY              -> RI
• MBR_FIND                -> MBR
• MBR_NOT_READABLE        -> MBR
• MBR_SELECTED            -> MBR
• MBR_SKIPPED             -> MBR
• MBR_READ_FROM           -> MBR
• MBW_FIND                -> MBW
• MBW_NOT_WRITEABLE       -> MBW
• MBW_SELECTED            -> MBW
• MBW_SKIPPED             -> MBW
• MBW_WRITE_TO            -> MBW
• WI_BEFORE               -> WI
• WI_AFTER                -> WI
• WI_SUMMARY              -> WI
• JSP_FORWARD             -> MVC

Feedback

This is extended version of user guide capture Tracing Support. I am looking forward to your comments bellow the post. You can also use Jersey mailing lists. Don't hesitate to report any bugs, feature, and/or improvement requests in Jersey JIRA issue tracker.

Thanks,
-lk