Filters: logBody("request", "response")

[bocytko]

Is your feature request related to a problem? Please describe.
I'd like to use skipper as proxy for APIs and log the request & response pairs, so that I can later mock the APIs.

Describe the solution you would like
Skipper already provides a filter logHeader to log request headers. Similarly, there could be a filter provided logBody that logs the request body/response (e.g. up to a certain size) (or a lua function that provides access to the request/response body).

Describe alternatives you've considered (optional)

• Running skipper as library and writing the filter myself.
• Tee'ing the response to another application that will do the logging.

Additional context (optional)

• nginx can do this (alternative)

Would you like to work on it?
No

[AlexanderYastrebov]

I think there is auditLog filter for this purpose (but we have it disabled in our deployment).

[bocytko]

I see. I used it and it seems the default when running skipper as library was 0 bytes. Will try again soon and close the issue if it works well.

[bocytko]

Skipper with auditLog() configured:

Simulated backend application:

$ ./bin/skipper -inline-routes='all: * -> inlineContent("<h1>response</h1>") -> <shunt>' -address=:9092

Request proxy:

$ ./bin/skipper -inline-routes='all: * -> auditLog() -> "http://localhost:9092"' -max-audit-body=1024

Request:

$ curl -v GET localhost:9090 -d 'a=b'

Logs:

$ ./bin/skipper -inline-routes='all: * -> auditLog() -> "http://localhost:9092"' -max-audit-body=1024
[APP]INFO[0000] Expose metrics in codahale format            
[APP]INFO[0000] enable swarm: false                          
[APP]INFO[0000] Replacing lua filter specification           
[APP]INFO[0000] support listener on :9911                    
[APP]INFO[0000] Dataclients are updated once, first load complete 
[APP]INFO[0000] proxy listener on :9090                      
[APP]INFO[0000] TLS settings not found, defaulting to HTTP   
[APP]INFO[0000] route settings, reset, route: all: * -> auditLog() -> "http://localhost:9092" 
[APP]INFO[0000] route settings received                      
[APP]ERRO[0000] Failed to start supportListener on :9911: listen tcp :9911: bind: address already in use 
[APP]INFO[0000] route settings applied                       
{"method":"POST","path":"/","status":200,"requestBody":"a=b"}
127.0.0.1 - - [25/Apr/2023:11:03:44 +0200] "POST / HTTP/1.1" 200 17 "-" "curl/7.81.0" 2 localhost:9090 - -

So auditLog logs the body of the request in the response filter.

I'm looking to log the request body in the request filter and the response body in the response filter, just like the logHeader filter does for headers.

[AlexanderYastrebov]

So auditLog logs the body of the request in the response filter.

This is done like that because request body is read only after request path of filter chain during backend request.

[szuecs]

As it's an auditlog you want to have request and response in the same line or "object" logged, because action X resulted in Y.
I think it makes sense to create a new logBody filter similar to logHeader.

[trkohler]

I want to try to implement it, if it's okay.

[szuecs]

@trkohler there is already a pr that has this as a side effect 😀
I try to build a facility for streaming filters. I start to check it again in the coming days and weeks.
#2428

[trkohler]

oh, just noticed your comment @szuecs 😅

[AlexanderYastrebov]

One idea for logging request/response body without buffering is to log it in chunks along with some kind of unique request/response id (memory address?) as soon as chunks are sent (i.e. intercept Body.Read and log what has been read).
The operator then may grep the logs for request id to find all the chunks of the same request. If most of bodies fit into one chunk (needs checking) then there will be mostly one log line per body.

[szuecs]

@AlexanderYastrebov do you mean %p of req.Body/rsp.Body?
Something like this:

[APP]INFO[0003] logBody("request") 0xc0001ae0c0: {"foo": "bar"}
[APP]INFO[0003] logBody("response") 0xc000457300: aaaaaaaaaa

[AlexanderYastrebov]

@szuecs Yes, this or maybe x-flow-id if present (and then document that it should be used like flowId("reuse") -> logBody("request"))

[szuecs]

@AlexanderYastrebov this would be the same in request and response, but I guess this is even better

I just pushed the change:

]% ./bin/skipper -inline-routes='* -> flowId("reuse") -> logBody("request", "response") -> "http://127.0.0.1:9001"'
[APP]INFO[0000] Expose metrics in codahale format
[APP]INFO[0000] enable swarm: false
[APP]INFO[0000] Replacing tee filter specification
[APP]INFO[0000] Replacing teenf filter specification
[APP]INFO[0000] Replacing lua filter specification
[APP]INFO[0000] support listener on :9911
[APP]INFO[0000] Dataclients are updated once, first load complete
[APP]INFO[0000] Listen on :9090
[APP]INFO[0000] route settings, reset, route: : * -> flowId("reuse") -> logBody("request", "response") -> "http://127.0.0.1:9001"
[APP]INFO[0000] route settings received
[APP]INFO[0000] route settings applied
[APP]INFO[0000] TLS settings not found, defaulting to HTTP
[APP]INFO[0002] logBody("request") Owx31+qpBJ6wfZUH: {"foo": "bar"}
[APP]INFO[0002] logBody("response") Owx31+qpBJ6wfZUH: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...
[APP]INFO[0002] logBody("response") Owx31+qpBJ6wfZUH: aaaaaaaaaaaaaaaaaaaa...

So chunks also work as expected