<?xml version="1.0" encoding="UTF-8"?>
<!--
<!DOCTYPE chapter PUBLIC "-//OASIS//DTD DocBook XML V4.4//EN"
                         "http://www.docbook.org/xml/4.4/docbookx.dtd">
 -->
<chapter id="Tracing_Feature">
    <title>RESTEasy Tracing Feature</title>
    <section>
        <title>Overview</title>
        <para>
            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.
        </para>
        <para>
            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.
        </para>
        <para>
            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.
        </para>
    </section>
    <section>
        <title>Tracing Info Mode</title>
        <para>The RESTEasy tracing feature supports three logging mode:
        </para>
        <itemizedlist>
            <listitem>OFF</listitem>
            <listitem>ON_DEMAND</listitem>
            <listitem>ALL</listitem>
        </itemizedlist>
        <para>
            "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.
        </para>
    </section>
    <section>
        <title>Tracing Info Level</title>
        <para>The tracing info has three levels:
        </para>
        <itemizedlist>
            <listitem>SUMMARY</listitem>
            <listitem>TRACE</listitem>
            <listitem>VERBOSE</listitem>
        </itemizedlist>
        <para>
            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.
        </para>
        <para>
            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.
        </para>
    </section>
    <section>
        <title>Basic Usages</title>
        <para>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:
            <programlisting><![CDATA[<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-tracing-api</artifactId>
</dependency>]]></programlisting>
        </para>
        <para>
            Because the tracing feature is an optional feature, the above dependency is provided by the
            <ulink url="https://github.com/resteasy/resteasy-extensions">resteasy-extensions</ulink>
            project.
        </para>
        <para>
            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:
            <programlisting><![CDATA[<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>]]></programlisting>
        </para>
        <para>
            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":

            <programlisting><![CDATA[# 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]]></programlisting>

            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.
        </para>
        <para>
            After enabling the tracing feature as shown above, we should get the tracing info output like following:
            <programlisting><![CDATA[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]]]></programlisting>

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

            <itemizedlist>
                <listitem>
                    <para>Level Of The Log Entry</para>
                    <para>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.
                    </para>
                </listitem>
                <listitem>
                    <para>The Request Scope Id</para>
                    <para>
                        We can see the request id like:
                        <programlisting><![CDATA[
org.jboss.resteasy.plugins.server.servlet.Servlet3AsyncHttpRequest@721299ff]]></programlisting>
                        So we can know which request the log entry belongs to.
                    </para>
                </listitem>
                <listitem>
                    <para>The Type Of The Tracing Log</para>
                    <para>tracing log entries are divided into multiple categories, such as
                        "START_HEADERS", "REQUEST_FILTER", "FINISHED", etc.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        The Detail Of The Log Entry
                    </para>
                    <para>The last part of a log entry is the detail message of this
                        entry.
                    </para>
                </listitem>
            </itemizedlist>

            In next section let's see how do we fetch the tracing info from client side.
        </para>
    </section>
    <section>
        <title>Client Side Tracing Info</title>
        <para>
            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:

            <programlisting><![CDATA[$ curl -i http://localhost:8081/foo]]></programlisting>

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

            <programlisting><![CDATA[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]]></programlisting>

            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".
        </para>
    </section>
    <section>
        <title>Json Formatted Response</title>
        <para>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:
            <programlisting><![CDATA[<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-jackson2-provider</artifactId>
</dependency>]]></programlisting>
        </para>
        <para>
            The second choice is to use the json-binding provider:

            <programlisting><![CDATA[<dependency>
    <groupId>org.jboss.resteasy</groupId>
    <artifactId>resteasy-json-binding-provider</artifactId>
</dependency>]]></programlisting>
        </para>
        <para>
            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):

            <programlisting><![CDATA[
$ curl -H "X-RESTEasy-Tracing-Accept-Format: JSON" -i http://localhost:8081/type]]></programlisting>

            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:

            <programlisting><![CDATA[
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"}]]]></programlisting>
        </para>
        <para>
            The above text is the raw output from response, and we can format it to make it readable:

            <programlisting><![CDATA[[{
    "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"
        }
    ]
}]]]></programlisting>
            From above we can see the tracing info is returned as JSON text.
        </para>
    </section>
    <section>
        <title>List Of Tracing Events</title>
        <para>
            The tracing events are defined in <ulink url="https://github.com/resteasy/resteasy-extensions/blob/master/tracing/src/main/java/org/jboss/resteasy/tracing/api/RESTEasyServerTracingEvent.java">RESTEasyServerTracingEvent</ulink>. Here is a complete list of the tracing events and its descriptions:

            <itemizedlist>
                <listitem>
                    <para>
                        DISPATCH_RESPONSE
                    </para>
                    <para>
                        Resource method invocation results to JAX-RS Response.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        EXCEPTION_MAPPING
                    </para>
                    <para>
                        ExceptionMapper invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        FINISHED
                    </para>
                    <para>
                        Request processing finished.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_LOCATOR
                    </para>
                    <para>
                        Matched sub-resource locator method.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_PATH_FIND
                    </para>
                    <para>
                        Matching path pattern.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_PATH_NOT_MATCHED
                    </para>
                    <para>
                        Path pattern not matched.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_PATH_SELECTED
                    </para>
                    <para>
                        Path pattern matched/selected.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_PATH_SKIPPED
                    </para>
                    <para>
                        Path pattern skipped as higher-priority pattern has been selected already.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_RESOURCE
                    </para>
                    <para>
                        Matched resource instance.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_RESOURCE_METHOD
                    </para>
                    <para>
                        Matched resource method.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_RUNTIME_RESOURCE
                    </para>
                    <para>
                        Matched runtime resource.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        MATCH_SUMMARY
                    </para>
                    <para>
                        Matching summary.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        METHOD_INVOKE
                    </para>
                    <para>
                        Resource method invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        PRE_MATCH
                    </para>
                    <para>
                        RESTEasy HttpRequestPreprocessor invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        PRE_MATCH_SUMMARY
                    </para>
                    <para>
                        RESTEasy HttpRequestPreprocessor invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        REQUEST_FILTER
                    </para>
                    <para>
                        ContainerRequestFilter invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        REQUEST_FILTER_SUMMARY
                    </para>
                    <para>
                        ContainerRequestFilter invocation summary.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        RESPONSE_FILTER
                    </para>
                    <para>
                        ContainerResponseFilter invoked.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        RESPONSE_FILTER_SUMMARY
                    </para>
                    <para>
                        ContainerResponseFilter invocation summary.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        START
                    </para>
                    <para>
                        Request processing started.
                    </para>
                </listitem>
                <listitem>
                    <para>
                        START_HEADERS
                    </para>
                    <para>
                        All HTTP request headers.
                    </para>
                </listitem>
            </itemizedlist>
        </para>
    </section>
    <section>
        <title>Tracing Example</title>
        <para>
            In the "resteasy-example" project, it contains a <ulink
                url="https://github.com/resteasy/resteasy-examples/tree/master/tracing-example">RESTEasy Tracing
            Example
        </ulink> to show the usages of tracing features. Please check the example to see the usages in action.
        </para>
    </section>
</chapter>