{8.1.0-new,8.2.0-updated} Logging / Debugging

The REST APIs provides support for fine-tuned control of logging for HTTP requests and responses.

The APIs involved are:

Request/response details

The amount of detail on requests and responses is controlled via the {@link oajr.annotation.LoggingRule#req() @LoggingRule(req)} and {@link oajr.annotation.LoggingRule#res() @LoggingRule(res)} annotations:

The following code shows the output produced using the "short" setting:

@Rest( logging=@Logging( level="info", rules={ @LoggingRule(codes"500-", level="warning", req="short", res="short") } ) ) public static class MyRestClass { @RestMethod(method="POST", path="foo") public String myRestMethod(RestRequest req, RestResponse res) throws Exception { res.setStatus(500); res.setHeader("Foo", "bar"); res.setException(new StringIndexOutOfBoundsException()); // Could also throw. return req.getBody().asString(); } } @Test public void test() throws Exception { MockRestClient.create(MyRestClass.class) .simpleJson() .build() .post<("/foo?foo=bar", "Foo") .header("Foo", "bar") .run() .assertStatus().is(500); }

The log output produced from the code above looks like this:

WARNING: [500] HTTP POST /foo java.lang.StringIndexOutOfBoundsException at org.apache.juneau.rest.annotation.RestResourceLoggingTest$MyRestClass.myRestMethod(RestResourceLoggingTest.java:672) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) ...

In comparison, using "long" formatting adds information about headers and body.

@Rest( debug="true", // Needed to capture request/response bodies for logging. logging=@Logging( level="info", rules={ @LoggingRule(codes"500-", level="warning", req="long", res="long") } ) )

Request/response bodies are only cached for logging if debugging is enabled via the debug="true" flag.

The log file now contains the following with shows the contents of the request and response bodies in both UTF-8 and spaced-hex:

WARNING: === HTTP Call (incoming) =================================================== [500] HTTP POST /foo?foo=bar Request length: 3 bytes Response code: 500 Response length: 3 bytes Exec time: 20ms ---Request Headers--- Foo: bar ---Response Headers--- Foo: bar Content-Type: text/plain ---Request Body UTF-8--- Foo ---Request Body Hex--- 46 6F 6F ---Response Body UTF-8--- Foo ---Response Body Hex--- 46 6F 6F === END =================================================================== java.lang.StringIndexOutOfBoundsException at org.apache.juneau.rest.annotation.RestResourceLoggingTest$MyRestClass.myRestMethod(RestResourceLoggingTest.java:672) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) ...

Rule matching

Logging rules can match against status codes, exception class names, and the debug flag.
The following shows various examples of logging rule matches.

@Rest( logging=@Logging( rules={ // Individual status codes. @LoggingRule(codes="300", ...) // Ranges of status codes. @LoggingRule(codes="400-499", ...) @LoggingRule(codes=">=500", ...) // All codes. @LoggingRule(codes="*", ...) // Full class names of exceptions. @LoggingRule(exceptions="java.lang.StringIndexOutOfBoundsException", ...) // Exception class name patterns. @LoggingRule(exceptions="String*Exception *Foo*Exception", ...) // Match when debug enabled only. @LoggingRule(codes="*", debugOnly="true", ...) } ) )

Rules are matched in the order listed on the annotation. Rules on methods are matched before rules on classes. Rules on child methods/classes are matched before rules on parent classes.

Debug mode

The debug mode setting allows HTTP request/response bodies to be cached in memory for logging purposes:

@Rest( debug="true" )

The possible values for the debug setting are (case-insensitive):

Note that caching HTTP bodies in memory can produce significant performance penalties, so use the setting wisely.
In particular, do not leave this setting enabled on production instances since it can easily lead to denial-of-service attacks.

Servlet code can check the debug setting via the {@link oajr.RestRequest#isDebug()} method allowing it to be used for custom purposes.

Debug mode can also be enabled on a request by calling the {@link oajr.RestRequest#setDebug(Boolean)} or {@link oajr.RestResponse#setDebug(Boolean)} methods. Note however that you must be sure not to have already consumed the request or started writing the response before calling this method.

No-trace (disabled) mode

The {@link oajr.annotation.Logging#disabled() @Logging(disabled)} and {@link oajr.annotation.LoggingRule#disabled() @LoggingRule(disabled)} annotations can be used to disable logging entirely or on a per-request basis:

@Rest( logging=@Logging( disabled="true" rules={ @LoggingRule( codes"500-", disabled="false" ) } ) )

The possible values for the disabled setting are (case-insensitive):

Disabled logging is particularly useful when running testcases that are expected to throw exceptions or cause other errors and you don't want these errors logged.

Disabled logging can also be set on a request by calling the {@link oajr.RestRequest#setNoTrace(Boolean)} or {@link oajr.RestResponse#setNoTrace(Boolean)} methods.

Stacktrace hashing

The {@link oajr.annotation.Logging#useStackTraceHashing() @Logging(useStackTraceHashing)} setting can be used to eliminate duplicate stacktraces in your log file by logging them once and then logging identifying hash IDs.

In the example below, we're causing two exceptions but only logging the first one:

@Rest( logging=@Logging( useStackTraceHashing="true", rules={ @LoggingRule(codes">=500", level="warning", req="short", res="short") } ) ) public static class MyRestClass { @RestMethod(method="POST", path="foo") public String myRestMethod(RestRequest req, RestResponse res) throws Exception { res.setHeader("Foo", "bar"); // Equivalent to throwing an exception. res.setStatus(500); res.setException(new StringIndexOutOfBoundsException()); return req.getBody().asString(); } } @Test public void test() throws Exception { MockRestClient.create(MyRestClass.class) .json() .build() .post("/foo?foo=bar", "Foo") .header("Foo", "bar") .run() .assertStatus().is(500); }

The log file will show a 4 byte hash ID "9b85cc96" and count ".1" as shown below:

Jul 11, 2019 3:38:48 PM org.apache.juneau.rest.BasicRestCallLogger log WARNING: [500,9b85cc96.1] HTTP POST /foo java.lang.StringIndexOutOfBoundsException at org.apache.juneau.rest.annotation.RestResourceLoggingTest$MyRestClass.myRestMethod(RestResourceLoggingTest.java:671) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) ... WARNING: [500,9b85cc96.2] HTTP POST /foo

The {@link oajr.annotation.Logging#stackTraceHashingTimeout() @Logging(stackTraceHashingTimeout)} setting can be used to periodically log the stacktrace to the log file again.