blob: 0c30ce8c8c0d12528328588cd38a140f0463086b [file] [log] [blame]
<!--
/***************************************************************************************************************************
* Licensed to the Apache Software Foundation (ASF) under one or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the
* specific language governing permissions and limitations under the License.
***************************************************************************************************************************/
-->
Logging / Debugging
<p>
The REST APIs provides support for fine-tuned control of logging for HTTP requests and responses.
</p>
<p>
The APIs involved are:
</p>
<ul class='javatree'>
<li class='ja'>
{@link oajr.annotation.Rest}
<ul>
<li class='jm'>{@link oajr.annotation.Rest#logging() logging()} - Class-level logging configuration and rules.
<li class='jm'>{@link oajr.annotation.Rest#debug() debug()} - Enable debug mode.
</ul>
</li>
<li class='ja'>
{@link oajr.annotation.RestMethod}
<ul>
<li class='jm'>{@link oajr.annotation.RestMethod#logging() logging()} - Class-level logging configuration.
<li class='jm'>{@link oajr.annotation.RestMethod#debug() debug()} - Enable debug mode.
</ul>
</li>
<li class='jc'>
{@link oajr.RestContext}
<ul>
<li class='jf'>{@link oajr.RestContext#REST_callLoggerConfig REST_callLoggerConfig} - Underlying configuration property for {@link oajr.annotation.Rest#logging() @Rest(logging)}.
<li class='jf'>{@link oajr.RestContext#REST_debug REST_debug} - Underlying configuration property for {@link oajr.annotation.Rest#debug() @Rest(debug)}.
</ul>
</li>
<li class='ja'>
{@link oajr.annotation.Logging} - Annotation for {@link oajr.annotation.Rest#logging() @Rest(logging)} and {@link oajr.annotation.RestMethod#logging() @RestMethod(logging)}
<ul>
<li class='jm'>{@link oajr.annotation.Logging#level() level()} - The logging level.
<li class='jm'>{@link oajr.annotation.Logging#rules() rules()} - The logging rules.
<li class='jm'>{@link oajr.annotation.Logging#useStackTraceHashing() useStackTraceHashing()} - Enables de-duplication of logged stack traces and replacement with hash IDs.
<li class='jm'>{@link oajr.annotation.Logging#stackTraceHashingTimeout() stackTraceHashingTimeout()} - Controls how frequently hashed stack traces are re-logged.
<li class='jm'>{@link oajr.annotation.Logging#disabled() disabled()} - Disables logging completely or per-request.
</ul>
</li>
<li class='ja'>
{@link oajr.annotation.LoggingRule} - Annotation for {@link oajr.annotation.Logging#rules() @Logging(rules)}
<ul>
<li class='jm'>{@link oajr.annotation.LoggingRule#level() level()} - The logging level.
<li class='jm'>{@link oajr.annotation.LoggingRule#codes() codes()} - Status code patterns and ranges to match against.
<li class='jm'>{@link oajr.annotation.LoggingRule#exceptions() exceptions()} - Exception class names and patterns to match against.
<li class='jm'>{@link oajr.annotation.LoggingRule#debugOnly() debugOnly()} - Match only if debug is set on the request.
<li class='jm'>{@link oajr.annotation.LoggingRule#req() req()} - The level of request detail.
<li class='jm'>{@link oajr.annotation.LoggingRule#res() res()} - The level of response detail.
<li class='jm'>{@link oajr.annotation.LoggingRule#verbose() verbose()} - Shortcut for <jsf>LONG</jsf> request and response detail.
<li class='jm'>{@link oajr.annotation.LoggingRule#disabled() disabled()} - Disables logging completely or per-request.
</ul>
</li>
</ul>
<h5 class='topic'>Request/response details</h5>
<p>
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:
</p>
<ul>
<li><js>"short"</js> - Results in simple one-line log lines containing the HTTP method + url + response code.
<li><js>"medium"</js> - Also includes headers and body length information (if debug enabled).
<li><js>"large"</js> - Dumps the entire request/response bodies (if debug enabled).
</ul>
<p>
The following code shows the output produced using the <js>"short"</js> setting:
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
logging=<ja>@Logging</ja>(
level=<js>"info"</js>,
rules={
<ja>@LoggingRule</ja>(codes<js>"500-"</js>, level=<js>"warning"</js>, req=<js>"short"</js>, res=<js>"short"</js>)
}
)
)
<jk>public static class</jk> MyRestClass {
<ja>@RestMethod</ja>(method=<js>"POST"</js>, path=<js>"foo"</js>)
<jk>public</jk> String myRestMethod(RestRequest req, RestResponse res) <jk>throws</jk> Exception {
res.setStatus(500);
res.setHeader(<js>"Foo"</js>, <js>"bar"</js>);
res.setException(<jk>new</jk> StringIndexOutOfBoundsException()); <jc>// Could also throw.</jc>
<jk>return</jk> req.getBody().asString();
}
}
<jk>static</jk> MockRest <jsf>MY_REST</jsf> = MockRest.<jsm>build</jsm>(MyRestClass.<jk>class</jk>, <jk>null</jk>);
<ja>@Test</ja>
<jk>public void</jk> test() <jk>throws</jk> Exception {
<jsf>MY_REST</jsf>.<jsm>post</jsm>(<js>"/foo?foo=bar"</js>, <js>"Foo"</js>).header(<js>"Foo"</js>, <js>"bar"</js>).execute().assertStatus(500);
}
</p>
<p>
The log output produced from the code above looks like this:
</p>
<p class='bpcode'>
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)
...
</p>
<p>
In comparison, using <js>"long"</js> formatting adds information about headers and body.
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
debug=<js>"true"</js>, <jc>// Needed to capture request/response bodies for logging.</jc>
logging=<ja>@Logging</ja>(
level=<js>"info"</js>,
rules={
<ja>@LoggingRule</ja>(codes<js>"500-"</js>, level=<js>"warning"</js>, req=<js>"long"</js>, res=<js>"long"</js>)
}
)
)
</p>
<p>
Request/response bodies are only cached for logging if debugging is enabled via the <c class='snippet'>debug=<js>"true"</js></c> flag.
</p>
<p>
The log file now contains the following with shows the contents of the request and response bodies in both UTF-8
and spaced-hex:
<p>
<p class='bpcode'>
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)
...
</p>
<h5 class='topic'>Rule matching</h5>
<p>
Logging rules can match against status codes, exception class names, and the debug flag.
<br>The following shows various examples of logging rule matches.
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
logging=<ja>@Logging</ja>(
rules={
<jc>// Individual status codes.</jc>
<ja>@LoggingRule</ja>(codes=<js>"300"</js>, ...)
<jc>// Ranges of status codes.</jc>
<ja>@LoggingRule</ja>(codes=<js>"400-499"</js>, ...)
<ja>@LoggingRule</ja>(codes=<js>">=500"</js>, ...)
<jc>// All codes.</jc>
<ja>@LoggingRule</ja>(codes=<js>"*"</js>, ...)
<jc>// Full class names of exceptions.</jc>
<ja>@LoggingRule</ja>(exceptions=<js>"java.lang.StringIndexOutOfBoundsException"</js>, ...)
<jc>// Exception class name patterns.</jc>
<ja>@LoggingRule</ja>(exceptions=<js>"String*Exception *Foo*Exception"</js>, ...)
<jc>// Match when debug enabled only.</jc>
<ja>@LoggingRule</ja>(codes=<js>"*"</js>, debugOnly=<js>"true"</js>, ...)
}
)
)
</p>
<p>
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.
</p>
<h5 class='topic'>Debug mode</h5>
<p>
The debug mode setting allows HTTP request/response bodies to be cached in memory for logging purposes:
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
debug=<js>"true"</js>
)
</p>
<p>
The possible values for the debug setting are (case-insensitive):
</p>
<ul>
<li><js>"true"</js> - Debug mode enabled.
<li><js>"false"</js> (default) - Debug mode disabled.
<li><js>"per-request"</js> - Debug mode is enabled only on requests containing an <c class='snippet'>X-Debug: true</c> header.
</ul>
<p>
Note that caching HTTP bodies in memory can produce significant performance penalties, so use the setting wisely.
<br>In particular, do not leave this setting enabled on production instances since it can easily lead to
denial-of-service attacks.
</p>
<p>
Servlet code can check the debug setting via the {@link oajr.RestRequest#isDebug()} method allowing it to be used
for custom purposes.
</p>
<p>
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.
</p>
<h5 class='topic'>No-trace (disabled) mode</h5>
<p>
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:
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
logging=<ja>@Logging</ja>(
disabled=<js>"true"</js>
rules={
<ja>@LoggingRule</ja>(
codes<js>"500-"</js>,
disabled=<js>"false"</js>
)
}
)
)
</p>
<p>
The possible values for the disabled setting are (case-insensitive):
</p>
<ul>
<li><js>"true"</js> - Logging disabled.
<li><js>"false"</js> (default) - Logging not disabled.
<li><js>"per-request"</js> - Logging is disabled only on requests containing a <c class='snippet'>X-NoTrace: true</c> header.
</ul>
<p>
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.
</p>
<p>
Disabled logging can also be set on a request by calling the {@link oajr.RestRequest#setNoTrace(Boolean)} or
{@link oajr.RestResponse#setNoTrace(Boolean)} methods.
</p>
<h5 class='topic'>Stacktrace hashing</h5>
<p>
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.
</p>
<p>
In the example below, we're causing two exceptions but only logging the first one:
</p>
<p class='bpcode'>
<ja>@Rest</ja>(
logging=<ja>@Logging</ja>(
useStackTraceHashing=<js>"true"</js>,
rules={
<ja>@LoggingRule</ja>(codes<js>">=500"</js>, level=<js>"warning"</js>, req=<js>"short"</js>, res=<js>"short"</js>)
}
)
)
<jk>public static class</jk> MyRestClass {
<ja>@RestMethod</ja>(method=<js>"POST"</js>, path=<js>"foo"</js>)
<jk>public</jk> String myRestMethod(RestRequest req, RestResponse res) <jk>throws</jk> Exception {
res.setHeader(<js>"Foo"</js>, <js>"bar"</js>);
// Equivalent to throwing an exception.
res.setStatus(500);
res.setException(<jk>new</jk> StringIndexOutOfBoundsException());
<jk>return</jk> req.getBody().asString();
}
}
<jk>static</jk> MockRest <jsf>MY_REST</jsf> = MockRest.<jsm>build</jsm>(MyRestClass.<jk>class</jk>, <jk>null</jk>);
<ja>@Test</ja>
<jk>public void</jk> test() <jk>throws</jk> Exception {
<jsf>MY_REST</jsf>.<jsm>post</jsm>(<js>"/foo?foo=bar"</js>, <js>"Foo"</js>).header(<js>"Foo"</js>, <js>"bar"</js>).execute().assertStatus(500);
<jsf>MY_REST</jsf>.<jsm>post</jsm>(<js>"/foo?foo=bar"</js>, <js>"Foo"</js>).header(<js>"Foo"</js>, <js>"bar"</js>).execute().assertStatus(500);
}
</p>
<p>
The log file will show a 4 byte hash ID <js>"9b85cc96"</js> and count <js>".1"</js> as shown below:
</p>
<p class='bpcode'>
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
</p>
<p>
The {@link oajr.annotation.Logging#stackTraceHashingTimeout() @Logging(stackTraceHashingTimeout)} setting can be used to periodically log the stacktrace
to the log file again.
</p>