<Logger name="intrafilter-logging" level="trace"/>
This version of the docs is a work in progress. If you don’t see what you are looking for check the legacy wiki. |
This page summarizes the different methods which can be used to get more information on the state of Repose and how it interacts with the clients, origin service, and third party services. Most of these methods can be used in a production deployment.
This should be used in a controlled environment (i.e. not production) and should not be used for more than a few minutes at a time due to the amount of logging that occurs. |
Intrafilter Logging allows you to see the modified output of each filter as the request goes through the filter chain which makes debugging configurations easier. This setting adds a UUID header to the request and another to the response.
When the logger is set to TRACE, you will see the following information:
Time stamp
UUID
Headers
Content (logged at the lowest level)
Status code
Request path
The TRACE setting is the most verbose logging setting. |
To enable intrafilter logging, the corresponding named log4j2 logger should be set to the TRACE
level.
This can be achieved by adding a line like the following to the log4j2.xml
file in your Repose configuration directory.
<Logger name="intrafilter-logging" level="trace"/>
This is an example of the log line that you will see for the request and for the response. These lines are formatted for convenience. The log line will be a single line without carriage returns.
{"preamble":"Intrafilter Request Log"
"timestamp":"2014-05-21T15:29:34.244-05:00"
"currentFilter":"client-auth"
"httpMethod":"GET","requestURI":"/"
"requestBody":""
"headers":{
"Intrafilter-Request-UUID":"db7e62b4-4923-2881-811d-49816ea77b63"
"Host":"localhost:10000"
"User-Agent":"Apache-HttpClient/4.2.5 (java 1.5)",
"Connection":"keep-alive"}}
{"preamble":"intrafilter Response Log"
"timestamp":"2014-05-21T17:44:38.161-05:00"
"currentFilter":"ip-identity"
"httpResponseCode":"200"
"responseBody":""
"headers":{
"Date":"Wed 21 May 2014 22:44:38 GMT"
"Intrafilter-Response-UUID":"95c37a94-6174-54de-8743-540b230bf8b7"
"Deproxy-Request-ID":"0d1a822e-68c8-4d67-866b-8aec45e9dfe0"
"Content-Length":"0"}}
Repose can report on which filters handled the client request and how long each filter took. This allows you to verify that all expected filters handled the request.
To enable this, add the following header to the client request:
x-trace-request: true
The Repose response to the client will contain the following header added to the response, one for each filter which handled the request:
x-[filter name]: [time]ms
The x-trace-request
header can be easily added to a test request using curl and the -H [header] flag.
For example:
curl -v -H "x-trace-request: true" http://localhost:8080/
The following example contains three headers which Repose added to the response. These headers indicate that the the client-auth, http-logging, and default-router all handled the request, taking 0, 6, and 0 ms respectively.
x-client-auth-time: 0ms x-http-logging-time: 6ms x-default-router-time: 0ms
You can view all of the data being sent and received to the origin service and other third party APIs (e.g. Identity) by turning on Apache HttpClient logging.
In log4j2.xml
, update the org.apache
logger to the debug
level. For example:
<Logger name="org.apache" level="debug"/>
Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,527 655550 [qtp1589228348-31] INFO org.openrepose.powerfilter.PowerFilter.trace-id-logging - Tracing header: {"requestId":"f863f80f-914d-4c01-a579-648673206a96","origin":null} Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,533 655556 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection request: [route: {}->http://localhost:8000][total kept alive: 0; route allocated: 0 of 200; total allocated: 0 of 400] Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,534 655557 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection leased: [id: 2][route: {}->http://localhost:8000][total kept alive: 0; route allocated: 1 of 200; total allocated: 1 of 400] Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,534 655557 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator - Connecting to localhost:8000 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,535 655558 [qtp1589228348-31] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: ignoreCookies Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,535 655558 [qtp1589228348-31] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,535 655558 [qtp1589228348-31] DEBUG org.apache.http.client.protocol.RequestTargetAuthentication - Target auth state: UNCHALLENGED Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,536 655559 [qtp1589228348-31] DEBUG org.apache.http.client.protocol.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,536 655559 [qtp1589228348-31] DEBUG org.apache.http.impl.client.DefaultHttpClient - Attempt 1 to execute request Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,536 655559 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Sending request: POST /post HTTP/1.1 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,536 655559 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "POST /post HTTP/1.1[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,537 655560 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "via: 1.1 localhost:8080 (Repose/7.2.2.0)[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,537 655560 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "x-forwarded-for: 0:0:0:0:0:0:0:1[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,537 655560 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Host: localhost:8000[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,537 655560 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "x-pp-user: repose_user[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,538 655561 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "x-trans-id: eyJyZXF1ZXN0SWQiOiJmODYzZjgwZi05MTRkLTRjMDEtYTU3OS02NDg2NzMyMDZhOTYiLCJvcmlnaW4iOm51bGx9[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,538 655561 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Accept-Encoding: gzip[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,538 655561 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Accept-Encoding: deflate[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,538 655561 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "User-Agent: HTTPie/0.9.2[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,538 655561 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Accept: application/json[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,539 655562 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Content-Type: application/json[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,539 655562 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Content-Length: 17[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,539 655562 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "Connection: Keep-Alive[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,539 655562 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> POST /post HTTP/1.1 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> via: 1.1 localhost:8080 (Repose/7.2.2.0) Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> x-forwarded-for: 0:0:0:0:0:0:0:1 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Host: localhost:8000 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> x-pp-user: repose_user Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> x-trans-id: eyJyZXF1ZXN0SWQiOiJmODYzZjgwZi05MTRkLTRjMDEtYTU3OS02NDg2NzMyMDZhOTYiLCJvcmlnaW4iOm51bGx9 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,540 655563 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Accept-Encoding: gzip Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Accept-Encoding: deflate Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> User-Agent: HTTPie/0.9.2 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Accept: application/json Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Content-Type: application/json Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Content-Length: 17 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,541 655564 [qtp1589228348-31] DEBUG org.apache.http.headers - >> Connection: Keep-Alive Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,542 655565 [qtp1589228348-31] DEBUG org.apache.http.wire - >> "{"server": "bob"}" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,543 655566 [qtp1589228348-31] DEBUG org.apache.http.wire - << "HTTP/1.1 200 OK[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,544 655567 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Server: gunicorn/19.4.1[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,544 655567 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Date: Fri, 04 Dec 2015 17:10:57 GMT[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,544 655567 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Connection: close[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,544 655567 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Content-Type: application/json[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,544 655567 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Content-Length: 652[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Access-Control-Allow-Origin: *[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.wire - << "Access-Control-Allow-Credentials: true[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.wire - << "[\r][\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Receiving response: HTTP/1.1 200 OK Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.headers - << HTTP/1.1 200 OK Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,545 655568 [qtp1589228348-31] DEBUG org.apache.http.headers - << Server: gunicorn/19.4.1 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Date: Fri, 04 Dec 2015 17:10:57 GMT Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Connection: close Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Content-Type: application/json Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Content-Length: 652 Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Access-Control-Allow-Origin: * Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,546 655569 [qtp1589228348-31] DEBUG org.apache.http.headers - << Access-Control-Allow-Credentials: true Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,547 655570 [qtp1589228348-31] DEBUG org.apache.http.wire - << "{[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,547 655570 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "args": {}, [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "data": "{\"server\": \"bob\"}", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "files": {}, [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "form": {}, [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "headers": {[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Accept": "application/json", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,548 655571 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Accept-Encoding": "gzip,deflate", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Connection": "Keep-Alive", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Content-Length": "17", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Content-Type": "application/json", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Host": "localhost:8000", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "User-Agent": "HTTPie/0.9.2", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,549 655572 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "Via": "1.1 localhost:8080 (Repose/7.2.2.0)", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,550 655573 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "X-Pp-User": "repose_user", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,550 655573 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "X-Trans-Id": "eyJyZXF1ZXN0SWQiOiJmODYzZjgwZi05MTRkLTRjMDEtYTU3OS02NDg2NzMyMDZhOTYiLCJvcmlnaW4iOm51bGx9"[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,550 655573 [qtp1589228348-31] DEBUG org.apache.http.wire - << " }, [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,550 655573 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "json": {[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,551 655574 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "server": "bob"[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,551 655574 [qtp1589228348-31] DEBUG org.apache.http.wire - << " }, [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,551 655574 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "origin": "0:0:0:0:0:0:0:1", [\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,551 655574 [qtp1589228348-31] DEBUG org.apache.http.wire - << " "url": "http://localhost:8000/post"[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,551 655574 [qtp1589228348-31] DEBUG org.apache.http.wire - << "}[\n]" Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,552 655575 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:60510<->127.0.0.1:8000 closed Trans-Id:f863f80f-914d-4c01-a579-648673206a96 - 2015-12-04 11:10:57,552 655575 [qtp1589228348-31] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:8000][total kept alive: 0; route allocated: 0 of 200; total allocated: 0 of 400]
Repose instruments its internal operations, such as the types of response codes returned from Repose or the origin service and the number of active requests. This information is published through JMX and can be accessed through any JMX client. JConsole is a popular choice to access information published through JMX as it is shipped with the JDK.
IN PROGRESS