JBoss.orgCommunity Documentation

第 55 章 RESTEasy Tracing Feature

55.1. Overview
55.2. Tracing Info Mode
55.3. Tracing Info Level
55.4. Basic Usages
55.5. Client Side Tracing Info
55.6. Json Formatted Response
55.7. List Of Tracing Events
55.8. Tracing Example

Tracing feature is a way for the users of the RESTEasy to understand what's going on internally in the container when a request is processed. It's different from the pure logging system or profiling feature, which provides more general information about the request and response.

The tracing feature provides more internal states of the JAX-RS container. For example, it could be able to show what filters a request is going through, or how long time a request is processed and other kinds of information.

Currently it doesn't have a standard or spec to define the tracing feature, so the tracing feature is tightly coupled with the concrete JAX-RS implementation itself. In this chapter, let's check the design and usage of the tracing feature.

The RESTEasy tracing feature supports three logging mode:

  • OFF
  • ON_DEMAND
  • ALL

"ALL" will enable the tracing feature. "ON_DEMAND" mode will give the control to client side: A client can send a tracing request via HTTP header and get the tracing info back from response headers. "OFF" mode will disable the tracing feature, and this is the default mode.

The tracing info has three levels:

  • SUMMARY
  • TRACE
  • VERBOSE

The "SUMMARY" level will emit some brief tracing information. The "TRACE" level will produce more detailed tracing information, and the "VERBOSE" level will generate extremely detailed tracing information.

The tracing feature relies on the JBoss Logging framework to produce the tracing info, so the JBoss Logging configuration actually controls the final output of the tracing info. So it is JBoss Logging framework configuration that controls the logging threshold of the tracing info.

By default, the tracing feature is turned off. If you want to enable the tracing feature, you need to add the following dependency in your project:

<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-tracing-api</artifactId>
</dependency>

Because the tracing feature is an optional feature, the above dependency is provided by the resteasy-extensions project.

After including the dependency in your project, you can set the tracing mode and tracing level via the context-param parameters in your web project’s web.xml file. Here is the example:

<context-param>
    <param-name>resteasy.server.tracing.type</param-name>
    <param-value>ALL</param-value>
    <param-name>resteasy.server.tracing.threshold</param-name>
    <param-value>SUMMARY</param-value>
</context-param>

Besides the above configuration, we also need to make sure that the underlying JBoss Logger is configured properly so it can output the tracing info as required. Here is an example of the "logging.properties":

# Additional logger names to configure (root logger is always configured)
#loggers=org.foo.bar, org.foo.baz
# Root logger level
logger.level=ALL
# Declare handlers for the root logger
logger.handlers=CONSOLE, FILE
# Declare handlers for additional loggers
#logger.org.foo.bar.handlers=XXX, YYY
# Console handler configuration
handler.CONSOLE=org.jboss.logmanager.handlers.ConsoleHandler
handler.CONSOLE.properties=autoFlush
handler.CONSOLE.level=ALL
handler.CONSOLE.autoFlush=true
handler.CONSOLE.formatter=PATTERN
# File handler configuration
handler.FILE=org.jboss.logmanager.handlers.FileHandler
handler.FILE.level=ALL
handler.FILE.properties=autoFlush,fileName
handler.FILE.autoFlush=true
handler.FILE.fileName=/tmp/jboss.log
handler.FILE.formatter=PATTERN
# The log format pattern for both logs
formatter.PATTERN=org.jboss.logmanager.formatters.PatternFormatter
formatter.PATTERN.properties=pattern
formatter.PATTERN.pattern=%d{HH:mm:ss,SSS} %-5p [%c{1}] %m%n

In above setting, we have set the logger level to "ALL", and output log file to "/tmp/jboss.log". In this case, we can make sure that we get all the tracing info.

After enabling the tracing feature as shown above, we should get the tracing info output like following:

16:21:40,110 INFO  [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff START baseUri=[http://localhost:8081/] requestUri=[http://localhost:8081/type] method=[GET] authScheme=[n/a] accept=n/a accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=n/a content-length=n/a  [ ---- ms]
16:21:40,110 TRACE [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff START_HEADERS Other request headers: Connection=[Keep-Alive] Host=[localhost:8081] User-Agent=[Apache-HttpClient/4.5.4 (Java/1.8.0_201)]  [ ---- ms]
16:21:40,114 INFO  [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff PRE_MATCH_SUMMARY PreMatchRequest summary: 0 filters [ 0.04 ms]
16:21:40,118 DEBUG [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff REQUEST_FILTER Filter by [io.weli.tracing.HttpMethodOverride @60353244] [ 0.02 ms]
...
16:21:40,164 INFO  [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff RESPONSE_FILTER_SUMMARY Response summary: 1 filters [ 8.11 ms]
16:21:40,164 INFO  [general] org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff FINISHED Response status: 200 [ ---- ms]

From the above tracing log output shown above, we can see that the entry of tracing log contains several parts:

  • Level Of The Log Entry

    We can see the log entries have different log levels, such as "TRACE", "INFO", "DEBUG". The tracing feature maps its own tracing info levels to the JBoss Logger output levels like this.

  • The Request Scope Id

    We can see the request id like:

    org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff

    So we can know which request the log entry belongs to.

  • The Type Of The Tracing Log

    tracing log entries are divided into multiple categories, such as "START_HEADERS", "REQUEST_FILTER", "FINISHED", etc.

  • The Detail Of The Log Entry

    The last part of a log entry is the detail message of this entry.

In next section let's see how do we fetch the tracing info from client side.

From client side, we can send request to the server side as usual, and if the server side is configured properly to produce tracing info, then the info will also be sent back to client side via response headers. For example, we can send request to the server like this:

$ curl -i http://localhost:8081/foo

And then we can get the tracing info from the response header like the following:

HTTP/1.1 200 OK
X-RESTEasy-Tracing-026: org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7a49a8aa MBW         [ ---- / 61.57 ms |  ---- %] [org.jboss.resteasy.plugins.providers.InputStreamProvider @1cbf0b08] is skipped
...
Date: Wed, 27 Mar 2019 09:39:50 GMT
Connection: keep-alive
X-RESTEasy-Tracing-000: org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7a49a8aa START       [ ---- /  ---- ms |  ---- %] baseUri=[http://localhost:8081/] requestUri=[http://localhost:8081/type] method=[GET] authScheme=[n/a] accept=*/* accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=n/a content-length=n/a
...
X-RESTEasy-Tracing-025: org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7a49a8aa MBW         [ ---- / 61.42 ms |  ---- %] [org.jboss.resteasy.plugins.providers.FileRangeWriter @35b791fa] is skipped

From above output, we can see the tracing info is in response headers, and it's marked in sequence as in the form of "X-RESTEasy-Tracing-nnn".

The tracing log can be returned to client side in JSON format. To use this feature, we need to choose a JSON provider for tracing module to generate JSON formatted info. There are two JSON providers you can choose from and they both support the JSON data marshalling. The first choice is to use the jackson2 provider:

<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-jackson2-provider</artifactId>
</dependency>

The second choice is to use the json-binding provider:

<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-json-binding-provider</artifactId>
</dependency>

After including either of the above module, we can send request to server to get the JSON formatted tracing info. Here is a request example(the example is provided at last section of this chapter):

$ curl -H "X-RESTEasy-Tracing-Accept-Format: JSON" -i http://localhost:8081/type

In the above curl command, we have added "X-RESTEasy-Tracing-Accept-Format: JSON" into request header, in this way we are requesting the json formatted tracing info from server, and the tracing info in response header is like the following:

X-RESTEasy-Tracing-000: [{"event":"START","duration":0,"timestamp":195286694509932,"text":"baseUri=[http://localhost:8081/] requestUri=[http://localhost:8081/type] method=[GET] authScheme=[n/a] accept=*/* accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=n/a content-length=n/a ","requestId":"org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"},{"event":"START_HEADERS","duration":0,"timestamp":195286695053606,"text":"Other request headers: Accept=[*/*] Host=[localhost:8081] User-Agent=[curl/7.54.0] X-RESTEasy-Tracing-Accept-Format=[JSON] ","requestId":"org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"}...{"event":"FINISHED","duration":0,"timestamp":195286729758836,"text":"Response status: 200","requestId":"org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"}]

The above text is the raw output from response, and we can format it to make it readable:

[{
    "X-RESTEasy-Tracing-000": [
        {
            "event": "START",
            "duration": 0,
            "timestamp": 195286694509932,
            "text": "baseUri=[http://localhost:8081/] requestUri=[http://localhost:8081/type] method=[GET] authScheme=[n/a] accept=*/* accept-encoding=n/a accept-charset=n/a accept-language=n/a content-type=n/a content-length=n/a ",
            "requestId": "org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"
        },
        {
            "event": "START_HEADERS",
            "duration": 0,
            "timestamp": 195286695053606,
            "text": "Other request headers: Accept=[*/*] Host=[localhost:8081] User-Agent=[curl/7.54.0] X-RESTEasy-Tracing-Accept-Format=[JSON] ",
            "requestId": "org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"
        },
        {
            "event": "PRE_MATCH_SUMMARY",
            "duration": 14563,
            "timestamp": 195286697637157,
            "text": "PreMatchRequest summary: 0 filters",
            "requestId": "org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"
        },
 ...
        {
            "event": "FINISHED",
            "duration": 0,
            "timestamp": 195286729758836,
            "text": "Response status: 200",
            "requestId": "org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@7f8a33b9"
        }
    ]
}]

From above we can see the tracing info is returned as JSON text.

The tracing events are defined in RESTEasyServerTracingEvent. Here is a complete list of the tracing events and its descriptions:

  • DISPATCH_RESPONSE

    Resource method invocation results to JAX-RS Response.

  • EXCEPTION_MAPPING

    ExceptionMapper invoked.

  • FINISHED

    Request processing finished.

  • MATCH_LOCATOR

    Matched sub-resource locator method.

  • MATCH_PATH_FIND

    Matching path pattern.

  • MATCH_PATH_NOT_MATCHED

    Path pattern not matched.

  • MATCH_PATH_SELECTED

    Path pattern matched/selected.

  • MATCH_PATH_SKIPPED

    Path pattern skipped as higher-priority pattern has been selected already.

  • MATCH_RESOURCE

    Matched resource instance.

  • MATCH_RESOURCE_METHOD

    Matched resource method.

  • MATCH_RUNTIME_RESOURCE

    Matched runtime resource.

  • MATCH_SUMMARY

    Matching summary.

  • METHOD_INVOKE

    Resource method invoked.

  • PRE_MATCH

    RESTEasy HttpRequestPreprocessor invoked.

  • PRE_MATCH_SUMMARY

    RESTEasy HttpRequestPreprocessor invoked.

  • REQUEST_FILTER

    ContainerRequestFilter invoked.

  • REQUEST_FILTER_SUMMARY

    ContainerRequestFilter invocation summary.

  • RESPONSE_FILTER

    ContainerResponseFilter invoked.

  • RESPONSE_FILTER_SUMMARY

    ContainerResponseFilter invocation summary.

  • START

    Request processing started.

  • START_HEADERS

    All HTTP request headers.

In the "resteasy-example" project, it contains a RESTEasy Tracing Example to show the usages of tracing features. Please check the example to see the usages in action.