Caddy: Add ability to log request body.

[itskenny0]

1. What version of Caddy are you running (caddy -version)?

any

2. What are you trying to do?

Log the entire request body.

In #858, the ability to log the request headers was added. However, my use case would require me to log the entire input. Would this be possible using a secondary placeholder, maybe?

[definitelycarter]

Do we want to log only certain request bodies either by type, length, both? I don't think we want to log out binary for example.

[itskenny0]

I personally would be interested in POST requests with application/json.

[mholt]

Just a few thoughts:

• How do we handle newlines (you want a log entry that spans an arbitrary number of lines?)
• How do we handle binary data?
• How do we handle huge request bodies (10+ MB... ?)

[itskenny0]

We already have a method to print the headers, which print newlines as \n. That sounds reasonable to me. The implementation by @definitelycarter restricts it to XML and JSON inputs, so binary shouldn't be an issue. A size limitation would be a good idea, however I'm not sure where the limitation should be put.

Maybe this feature would be good in a seperate plugin, which would allow for some configurability.

[definitelycarter]

How do we handle newlines

I saw this code used in a couple of replacers; However, In my testing I found newlines were not getting logged so I decided to leave it out.

How do we handle binary data?

I'm currently limiting the logging done based on the Content-Type parameter. Now that I think of it, It probably won't stop someone from posting binary data with Content-Type of application/json. Should we use DetectContentType?

How do we handle huge request bodies (10+ MB... ?)

Currently I'm copying the entire body. What would be a good default limit?

[slightfoot]

Would this feature just be used for development/debugging? If so then wouldn't a middle-ware host dashboard be better. Like /debug/requests and see a live request log with the ability to expand/collapse stuff and all that jazz.

[mholt]

@slightfoot That's a totally separate beast, and it'll come, I'm working on it.

[itskenny0]

I would definitely require a log though (part of the reason I want this is to be able to replay for debugging). A live view wouldn't suffice as it wouldn't save the requests to disk.

[definitelycarter]

Hey @itskenny0,

It's now possible to log request bodies up to 100 KB with {request_body}

Thanks!

[itskenny0]

First of all, thanks for implementing this. Unfortunately, I can't get it to work.

I currently get this output:
xxx.xxx.xxx.xxx 17/Aug/2016:11:26:57 +0200 POST /xxx/xxx.php HTTP/1.1 200 23 - 55ms || POST /xxx/xxx.php HTTP/1.1\r\nHost: xxx.xxx\r\nConnection: keep-alive\r\nContent-Length: 229\r\nContent-Type: application/json\r\n\r\n || BODY: -

My log directive looks like this:

log / /www/xxx.xxx/access.log "{remote} {when} {method} {uri} {proto} {status} {size} {>User-Agent} {latency} || {request} || BODY: {request_body}"

[itskenny0]

Also here's how I can reproduce this:

curl -H "Content-Type: application/json" -X POST -d '{"username":"xyz","password":"xyz"}' https://domain.com/test.php

xxx.xxx.xxx.xxx 17/Aug/2016:11:44:16 +0200 POST /test.php HTTP/1.1 200 0 curl/7.35.0 1ms || REQUEST: POST /test.php HTTP/1.1\r\nHost: domain.com\r\nAccept: */*\r\nContent-Length: 35\r\nContent-Type: application/json\r\nUser-Agent: curl/7.35.0\r\n\r\n || BODY: -

[mholt]

Works for me!

Caddyfile:

localhost

log / stderr "{remote} {when} {method} {uri} {proto} {status} {size} {>User-Agent} {latency} || {request} || BODY: {request_body}"

Log after using that curl command:

::1 17/Aug/2016:09:35:34 -0600 POST / HTTP/1.1 404 14 curl/7.43.0 167µs || POST / HTTP/1.1\r\nHost: localhost:2015\r\nAccept: */*\r\nContent-Length: 35\r\nContent-Type: application/json\r\nUser-Agent: curl/7.43.0\r\n\r\n || BODY: {"username":"xyz","password":"xyz"}

[abiosoft]

@itskenny0 which version of Caddy are you running ?

[itskenny0]

This is the entire host directive:

domain.com {
        tls [email protected]

        browse
        root /www/domain.com/htdocs/
        gzip
        log / /www/domain.com/access.log "{remote} {when} {method} {uri} {proto} {status} {size} {>User-Agent} {latency} || {request} || BODY: {request_body}"
        errors /www/domain.com/error.log
        fastcgi / /var/run/php5-fpm.sock php

        header / Strict-Transport-Security "max-age=31536000"

        internal /git/listenerbot/.git
        git {
                repo https://github.com/itskenny0/listenerbot
                then git submodule update --init --recursive
                path git/listenerbot
                interval 120
        }
}

Do you see anything that could cause this?
Also, just to clarify, I got the latest caddy by go-getting caddy-git (since I need this) and caddydev, then used caddydev to generate a binary which is the one I'm using. Since Caddy seems to be replacing the {request_body} with a hyphen (as opposed to before where it would just leave it), it seems the code is present.

Please let me know if I can add any details that would help explain this.

//EDIT: Caddy won't tell me a version.

root@www:/opt/caddy# caddy -version
Caddy (untracked dev build)

[mholt]

@itskenny0 Use the build.bash script in the caddy folder to get proper version information, that will help us out. :+1:

[itskenny0]

Manually building it, it gives me this:

root@www:/opt/go/src/github.com/mholt/caddy/caddy# ./caddy -version
Caddy 0.9.0 (+745ae6f Wed Aug 17 15:52:26 UTC 2016)

However, this one doesn't include the Git addon, which is why I can't put it in production and test this exact binary. I'm not sure if caddydev built the same binary version.

[mholt]

So is it fixed now that we know it's the latest version?

[itskenny0]

Well, as I said, I can't test this exact binary unfortunately as I need the Git module built in to run it in place of the existing Caddy I use. Could you tell me how I use the build.bash while including the Git module?

[mholt]

Just add _ "github.com/abiosoft/caddy-git" to the imports in run.go and re-build.

[itskenny0]

Thank you. I did that, and it builds correctly, but unfortunately the body is still only a hyphen.

Caddy 0.9.0 (+745ae6f Wed Aug 17 16:14:33 UTC 2016)
 1 file changed, 2 insertions(+)
caddy/caddymain/run.go

[mholt]

It works for me with your full Caddyfile and on the same build version. :confused: Not sure what else to suggest at this point.

[definitelycarter]

I have seen that when an empty body is printed (i.e. GET request). Can you try removing some of the directives and try again?

[itskenny0]

I was able to narrow it down to the fastcgi directive.
fastcgi / /var/run/php5-fpm.sock php

Once I remove this, the request body is correctly logged. Any advice?

[definitelycarter]

I'd help test; However, I'm having difficulty setting up php to test fastcgi on my machine. My thought is that fastcgi is consuming the body before log is able to read it.

EDIT: I am able to reproduce it with the proxy directive and my suspicion is correct. I will propose a fix shortly.

[definitelycarter]

Well - my first thought was to capture the result rep.Replace before l.Next.Invoke is called. The problem I have now is that {latency} will not be correct. @mholt any ideas?

[tw4452852]

Ah, I know what is the culprit. Because we capture the request's body after the following middlewares done, if one of them consumes the entire (or part of) body, we will get empty (or part of) body. I will give a fix later.

[itskenny0]

Hi guys, I have just tested the latest commit on this matter and unfortunately I still can't log the request body if fastcgi is enabled. Same symptoms as before.

root@www:/opt/caddy# ./caddy -version
Caddy 0.9.1 (+1d3212a Sun Aug 21 14:15:30 UTC 2016)
 1 file changed, 2 insertions(+)
caddy/caddymain/run.go

//EDIT: I just realized that commit was to another repo and the pull request has not been merged yet. Sorry. It does work if I clone the right repo. Thanks!

//EDIT2: I do have another bug though, the body is cut off. The request sent looks like this:

{"update_id":182354273,
"message":{"message_id":260358,"from":{"id":12345678,"first_name":"User","last_name":""},"chat":{"id":-1001045412296,"title":"user\ud83c\udf52\ud83c\udf89","username":"user","type":"supergroup"},"date":1471789794,"text":"text"}}

Caddy logs this:

xxx.xxx.xxx.xxx 21/Aug/2016:16:29:54 +0200 POST /static/file.php HTTP/1.1 200 23 - 47ms || REQUEST: POST /static/file.php HTTP/1.1\r\nHost: domain.com\r\nConnection: keep-alive\r\nContent-Length: 310\r\nContent-Type: application/json\r\n\r\n || BODY: -,"chat":-,"date":1471789794,"text":"text"}}

[tw4452852]

@itskenny0 For edit 2, does it happen with fix patch?

[itskenny0]

It does. I'm not sure if it happens before the fix, I can test that later if relevant.

On Aug 22, 2016, at 2:31 AM, Tw [email protected] wrote:

@itskenny0 For edit 2, does it happen with fix patch?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[tw4452852]

@itskenny0 , Thanks for reporting. Yes it's a bug. It recognized { in request's body as a place holder which is not our expected. And now I have refined my patch to fix it. Give it a try again?

[itskenny0]

Yes, this seems perfect.

xxx.xxx.xxx.xxx 22/Aug/2016:21:08:31 +0200 POST /test.php HTTP/1.1 200 23 - 50ms || REQUEST: POST /test.php HTTP/1.1\r\nHost: domain.com\r\nConnection: keep-alive\r\nContent-Length: 302\r\nContent-Type: application/json\r\n\r\n || BODY: {"update_id":182392271,\n"message":{"message_id":1163439,"from":{"id":163275918,"first_name":"user","last_name":".","username":"user"},"chat":{"id":-10010507343434,"title":"user \ud83d\udc45 \ud83d\udca6 \ud83d\udd25","username":"user","type":"supergroup"},"date":1471892911,"text":"test"}}

Thank you!

[tw4452852]

Hi @itskenny0 , I think we could close this issue for now because the patch has been merged.
Feel free to reopen if you have any problems. Thanks.

[Dejab555]

Hi, is that not available for the 'errors.log' ?

I've tried that:
errors / /var/log/errors.log "{remote} {when} {method} {uri} {proto} {status} {size} || BODY: {request_body}"
and caddy won't even create the log file.

[francislavoie]

@MariusWiencke I think you want https://caddyserver.com/docs/log, not errors. log prints every request (think of it like an access log) whereas errors only prints when there's an error 😛

[Dejab555]

@francislavoie yeah but what if the post data on a requests caused the error ?
That request goes to the error log not the normal log and you have currently no chance to log that like:

errors / /var/log/errors.log "{remote} {when} {method} {uri} {proto} {status} {size} || BODY: {request_body}"

You know what i mean?

[itskenny0]

@MariusWiencke Errored requests will be logged to both the access log and the error log.