{8.1.0-new} Logging / Debugging

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

The APIs involved are:

- {@link oajr.annotation.Rest}
  - {@link oajr.annotation.Rest#logging() logging()} - Class-level logging configuration and rules.
  - {@link oajr.annotation.Rest#debug() debug()} - Enable debug mode.
- {@link oajr.annotation.RestMethod}
  - {@link oajr.annotation.RestMethod#logging() logging()} - Class-level logging configuration.
  - {@link oajr.annotation.RestMethod#debug() debug()} - Enable debug mode.
- {@link oajr.RestContext}
  - {@link oajr.RestContext#REST_callLoggerConfig REST_callLoggerConfig} - Underlying configuration property for {@link oajr.annotation.Rest#logging() @Rest(logging)}.
  - {@link oajr.RestContext#REST_debug REST_debug} - Underlying configuration property for {@link oajr.annotation.Rest#debug() @Rest(debug)}.
- {@link oajr.annotation.Logging} - Annotation for {@link oajr.annotation.Rest#logging() @Rest(logging)} and {@link oajr.annotation.RestMethod#logging() @RestMethod(logging)}
  - {@link oajr.annotation.Logging#level() level()} - The logging level.
  - {@link oajr.annotation.Logging#rules() rules()} - The logging rules.
  - {@link oajr.annotation.Logging#useStackTraceHashing() useStackTraceHashing()} - Enables de-duplication of logged stack traces and replacement with hash IDs.
  - {@link oajr.annotation.Logging#stackTraceHashingTimeout() stackTraceHashingTimeout()} - Controls how frequently hashed stack traces are re-logged.
  - {@link oajr.annotation.Logging#disabled() disabled()} - Disables logging completely or per-request.
- {@link oajr.annotation.LoggingRule} - Annotation for {@link oajr.annotation.Logging#rules() @Logging(rules)}
  - {@link oajr.annotation.LoggingRule#level() level()} - The logging level.
  - {@link oajr.annotation.LoggingRule#codes() codes()} - Status code patterns and ranges to match against.
  - {@link oajr.annotation.LoggingRule#exceptions() exceptions()} - Exception class names and patterns to match against.
  - {@link oajr.annotation.LoggingRule#debugOnly() debugOnly()} - Match only if debug is set on the request.
  - {@link oajr.annotation.LoggingRule#req() req()} - The level of request detail.
  - {@link oajr.annotation.LoggingRule#res() res()} - The level of response detail.
  - {@link oajr.annotation.LoggingRule#verbose() verbose()} - Shortcut for LONG request and response detail.
  - {@link oajr.annotation.LoggingRule#disabled() disabled()} - Disables logging completely or per-request.

##### 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:

- "short" - Results in simple one-line log lines containing the HTTP method + url + response code.
- "medium" - Also includes headers and body length information (if debug enabled).
- "large" - Dumps the entire request/response bodies (if debug enabled).

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(); } } static MockRest MY_REST = MockRest.build(MyRestClass.class, null); @Test public void test() throws Exception { MY_REST.post("/foo?foo=bar", "Foo").header("Foo", "bar").execute().assertStatus(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 Request (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):

- "true" - Debug mode enabled.
- "false" (default) - Debug mode disabled.
- "per-request" - Debug mode is enabled only on requests containing an X-Debug: true header.

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):

- "true" - Logging disabled.
- "false" (default) - Logging not disabled.
- "per-request" - Logging is disabled only on requests containing a X-NoTrace: true header.

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(); } } static MockRest MY_REST = MockRest.build(MyRestClass.class, null); @Test public void test() throws Exception { MY_REST.post("/foo?foo=bar", "Foo").header("Foo", "bar").execute().assertStatus(500); MY_REST.post("/foo?foo=bar", "Foo").header("Foo", "bar").execute().assertStatus(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.