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.