Apacheとnginxで、HTTPリクエストボディを記録する

これは、なにをしたくて書いたもの？

デバッグ等でHTTP POSTやHTTP PUTで送信したHTTPリクエストボディを確認したくなることがありますが、その方法はいろいろあります。

たいていは、アプリケーションのログに出力するようにして済ませたり、tcpdumpなどで確認することは自分は多いのですが。
これをApacheやnginxでやる場合には？ということで、ちょっとメモしてみました。

定常的に適用しておくようなものではありませんが、知っておくと便利かな、と。

環境

今回の環境はこちら。Ubuntu Linux 20.04 LTSです。

$ uname -srvmpio
Linux 5.4.0-124-generic #140-Ubuntu SMP Thu Aug 4 02:23:37 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux


$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.4 LTS
Release:        20.04
Codename:       focal

Apacheとnginxのインストール

まずは、Apacheとnginxをインストールしておきます。

Apacheから。

$ sudo apt install apache2

バージョン。

$ apache2 -v
Server version: Apache/2.4.41 (Ubuntu)
Server built:   2022-06-14T13:30:55

インストールした時点で起動しているので、停止しておきます。

$ sudo systemctl stop apache2

nginxは、以下のドキュメントに従ってインストールします。

nginx: Linux packages / Ubuntu

$ sudo apt install curl gnupg2 ca-certificates lsb-release ubuntu-keyring
$ curl https://nginx.org/keys/nginx_signing.key | gpg --dearmor \
    | sudo tee /usr/share/keyrings/nginx-archive-keyring.gpg >/dev/null
$ gpg --dry-run --quiet --import --import-options import-show /usr/share/keyrings/nginx-archive-keyring.gpg
$ echo "deb [signed-by=/usr/share/keyrings/nginx-archive-keyring.gpg] \
http://nginx.org/packages/ubuntu `lsb_release -cs` nginx" \
    | sudo tee /etc/apt/sources.list.d/nginx.list
$ sudo apt update
$ sudo apt install nginx

バージョン。

$ nginx -v
nginx version: nginx/1.22.0

nginxは、インストールしても明示的に起動しない限りは停止したままになっています。

なんらかの理由で起動した場合は、停止はsystemctlで。

$ sudo systemctl stop nginx

確認方法

単純にApacheやnginxを立てただけではHTTPリクエストボディを受け付けるようなコンテンツはないので、リバースプロキシにして
バックエンドのサーバーに応答を返してもらうようにしてもらいましょう。

バックエンドには、http-echoを使うことにします。

GitHub - hashicorp/http-echo: A tiny go web server that echos what you start it with!

インストール。

$ curl -LO https://github.com/hashicorp/http-echo/releases/download/v0.2.3/http-echo_0.2.3_linux_amd64.tar.gz
$ tar xf http-echo_0.2.3_linux_amd64.tar.gz

起動。

$ ./http-echo -listen=:8080 -text='Hello World'

確認。

$ curl -XPOST localhost:8080 -d '{"message": "logging request"}'
Hello World

このサーバーのリバースプロキシとしてApacheやnginxを構成し、その時にHTTPリクエストボディを記録するようにしてみます。

Apacheの場合

Apacheの場合は、mod_dumpioを導入する必要があります。

mod_dumpio - Apache HTTP Server Version 2.4

mod_dumpioは、Apacheに対する入力およびApacheが出力する内容をエラーログに出力するモジュールです。

mod_dumpio allows for the logging of all input received by Apache and/or all output sent by Apache to be logged (dumped) to the error.log file.

大量のデータが記録される可能性があるので、デバッグ用途のみで使うように注意が書かれています。

The data logging is done right after SSL decoding (for input) and right before SSL encoding (for output). As can be expected, this can produce extreme volumes of data, and should only be used when debugging problems.

SSL／TLSが適用されていても、復号された後（または暗号化される前）の内容が記録されるようです。

Ubuntu LinuxでインストールしたApacheの場合は、以下のコマンドでmod_dumpioモジュールを有効化できます。

$ sudo a2enmod dump_io
Enabling module dump_io.
To activate the new configuration, you need to run:
  systemctl restart apache2

設定ファイルを作成します。

/etc/apache2/conf-enabled/dump-io.conf

LogLevel dumpio:trace7

DumpIOInput On

mod_dumpioには、入力を記録するDumpIOInputと出力を記録するDumpIOOutputという2つのディレクティブがあります。

まずはDumpIOInputをOnにしてみます。

また、ログレベルをtrace7にする必要があります。

Additionally, mod_dumpio needs to be configured to LogLevel trace7

全体のログレベルを下げるのもなんなので、mod_dumpioのみtrace7にしておきました。

LogLevel dumpio:trace7

あとは、mod_proxy_httpを導入して

$ sudo a2enmod proxy_http

リバースプロキシとして構成します。

/etc/apache2/conf-enabled/proxy-http.conf

ProxyPass / http://localhost:8080/
ProxyPassReverse / http://localhost:8080/

ここまでできたら、Apacheを起動。

$ sudo systemctl restart apache2

Apache経由で、http-echoにリクエストを送信します。

$ curl -XPOST localhost -d '{"message": "logging request"}'
Hello World

この時、Apacheのエラーログを確認すると、大量のログが出力されているのがわかります。

/var/log/apache2/error.log

[Tue Aug 16 00:05:29.950514 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950589 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:05:29.950595 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): POST / HTTP/1.1\r\n
[Tue Aug 16 00:05:29.950601 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950605 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:05:29.950608 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): Host: localhost\r\n
[Tue Aug 16 00:05:29.950611 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950614 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 25 bytes
[Tue Aug 16 00:05:29.950617 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): User-Agent: curl/7.68.0\r\n
[Tue Aug 16 00:05:29.950620 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950623 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 13 bytes
[Tue Aug 16 00:05:29.950625 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): Accept: */*\r\n
[Tue Aug 16 00:05:29.950628 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950631 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 20 bytes
[Tue Aug 16 00:05:29.950634 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): Content-Length: 30\r\n
[Tue Aug 16 00:05:29.950637 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950639 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 49 bytes
[Tue Aug 16 00:05:29.950642 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): Content-Type: application/x-www-form-urlencoded\r\n
[Tue Aug 16 00:05:29.950645 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.950648 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 2 bytes
[Tue Aug 16 00:05:29.950650 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): \r\n
[Tue Aug 16 00:05:29.950874 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [readbytes-blocking] 30 readbytes
[Tue Aug 16 00:05:29.950915 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): 30 bytes
[Tue Aug 16 00:05:29.950919 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): {"message": "logging request"}
[Tue Aug 16 00:05:29.951154 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951422 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:05:29.951433 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): HTTP/1.1 200 OK\r\n
[Tue Aug 16 00:05:29.951442 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951446 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 23 bytes
[Tue Aug 16 00:05:29.951449 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X-App-Name: http-echo\r\n
[Tue Aug 16 00:05:29.951453 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:05:29.951468 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951471 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X
[Tue Aug 16 00:05:29.951476 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951497 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951500 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X
[Tue Aug 16 00:05:29.951503 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 21 bytes
[Tue Aug 16 00:05:29.951505 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): -App-Version: 0.2.3\r\n
[Tue Aug 16 00:05:29.951509 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:05:29.951512 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951515 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): D
[Tue Aug 16 00:05:29.951518 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951521 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951534 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): D
[Tue Aug 16 00:05:29.951537 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 36 bytes
[Tue Aug 16 00:05:29.951540 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ate: Mon, 15 Aug 2022 15:05:29 GMT\r\n
[Tue Aug 16 00:05:29.951549 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:05:29.951552 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951556 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:05:29.951563 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951566 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951569 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:05:29.951572 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 19 bytes
[Tue Aug 16 00:05:29.951575 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ontent-Length: 12\r\n
[Tue Aug 16 00:05:29.951578 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:05:29.951582 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951584 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:05:29.951588 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951591 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951594 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:05:29.951597 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 40 bytes
[Tue Aug 16 00:05:29.951600 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ontent-Type: text/plain; charset=utf-8\r\n
[Tue Aug 16 00:05:29.951603 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:05:29.951606 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951609 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \r
[Tue Aug 16 00:05:29.951613 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:05:29.951616 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951619 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \r
[Tue Aug 16 00:05:29.951622 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:05:29.951625 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \n
[Tue Aug 16 00:05:29.951636 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [readbytes-nonblocking] 12 readbytes
[Tue Aug 16 00:05:29.951639 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 12 bytes
[Tue Aug 16 00:05:29.951643 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): Hello World\n
[Tue Aug 16 00:05:29.951684 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [speculative-nonblocking] 1 readbytes
[Tue Aug 16 00:05:29.953104 2022] [dumpio:trace7] [pid 6014:tid 140116790077184] mod_dumpio.c(135): [client 127.0.0.1:34884] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes

HTTPリクエストボディのみならず、HTTPヘッダーも出力されています。

[Tue Aug 16 00:05:29.950919 2022] [dumpio:trace7] [pid 6014:tid 140116781684480] mod_dumpio.c(100): [client 127.0.0.1:34884] mod_dumpio:  dumpio_in (data-HEAP): {"message": "logging request"}

ところで、よくよく見るとHTTPレスポンスに関する内容も含まれているようです。

DumpIOOutputもOnにして、どう変化するか見てみましょう。

/etc/apache2/conf-enabled/dump-io.conf

LogLevel dumpio:trace7

DumpIOInput On
DumpIOOutput On

Apacheを再起動。

$ sudo systemctl restart apache2

もう1度、リクエストを送信。

$ curl -XPOST localhost -d '{"message": "logging request"}'
Hello World

すると、/var/log/apache2/error.logに記録される内容がさらに増えました。

[Tue Aug 16 00:12:04.291774 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291872 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:12:04.291877 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): POST / HTTP/1.1\r\n
[Tue Aug 16 00:12:04.291884 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291888 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:12:04.291891 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): Host: localhost\r\n
[Tue Aug 16 00:12:04.291894 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291898 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 25 bytes
[Tue Aug 16 00:12:04.291901 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): User-Agent: curl/7.68.0\r\n
[Tue Aug 16 00:12:04.291904 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291908 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 13 bytes
[Tue Aug 16 00:12:04.291911 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): Accept: */*\r\n
[Tue Aug 16 00:12:04.291914 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291917 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 20 bytes
[Tue Aug 16 00:12:04.291920 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): Content-Length: 30\r\n
[Tue Aug 16 00:12:04.291924 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291927 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 49 bytes
[Tue Aug 16 00:12:04.291930 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): Content-Type: application/x-www-form-urlencoded\r\n
[Tue Aug 16 00:12:04.291933 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.291936 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 2 bytes
[Tue Aug 16 00:12:04.291939 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): \r\n
[Tue Aug 16 00:12:04.292163 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [readbytes-blocking] 30 readbytes
[Tue Aug 16 00:12:04.292172 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): 30 bytes
[Tue Aug 16 00:12:04.292176 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_in (data-HEAP): {"message": "logging request"}
[Tue Aug 16 00:12:04.292261 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(164): [remote 127.0.0.1:8080] mod_dumpio: dumpio_out
[Tue Aug 16 00:12:04.292269 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 17 bytes
[Tue Aug 16 00:12:04.292272 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): POST / HTTP/1.1\r\n
[Tue Aug 16 00:12:04.292275 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 22 bytes
[Tue Aug 16 00:12:04.292278 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): Host: localhost:8080\r\n
[Tue Aug 16 00:12:04.292282 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 25 bytes
[Tue Aug 16 00:12:04.292285 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): User-Agent: curl/7.68.0\r\n
[Tue Aug 16 00:12:04.292288 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 13 bytes
[Tue Aug 16 00:12:04.292291 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): Accept: */*\r\n
[Tue Aug 16 00:12:04.292294 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 49 bytes
[Tue Aug 16 00:12:04.292297 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): Content-Type: application/x-www-form-urlencoded\r\n
[Tue Aug 16 00:12:04.292300 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 28 bytes
[Tue Aug 16 00:12:04.292303 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): X-Forwarded-For: 127.0.0.1\r\n
[Tue Aug 16 00:12:04.292306 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 29 bytes
[Tue Aug 16 00:12:04.292309 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): X-Forwarded-Host: localhost\r\n
[Tue Aug 16 00:12:04.292312 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 44 bytes
[Tue Aug 16 00:12:04.292315 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): X-Forwarded-Server: ubuntu2004.localdomain\r\n
[Tue Aug 16 00:12:04.292318 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 20 bytes
[Tue Aug 16 00:12:04.292321 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): Content-Length: 30\r\n
[Tue Aug 16 00:12:04.292324 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): 24 bytes
[Tue Aug 16 00:12:04.292332 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-POOL): Connection: Keep-Alive\r\n
[Tue Aug 16 00:12:04.292336 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-IMMORTAL): 2 bytes
[Tue Aug 16 00:12:04.292339 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-IMMORTAL): \r\n
[Tue Aug 16 00:12:04.292342 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-HEAP): 30 bytes
[Tue Aug 16 00:12:04.292345 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-HEAP): {"message": "logging request"}
[Tue Aug 16 00:12:04.292348 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes
[Tue Aug 16 00:12:04.292385 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.292801 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 17 bytes
[Tue Aug 16 00:12:04.292822 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): HTTP/1.1 200 OK\r\n
[Tue Aug 16 00:12:04.292831 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.292837 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 23 bytes
[Tue Aug 16 00:12:04.292841 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X-App-Name: http-echo\r\n
[Tue Aug 16 00:12:04.292846 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:12:04.292851 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292855 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X
[Tue Aug 16 00:12:04.292860 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.292877 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292883 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): X
[Tue Aug 16 00:12:04.292887 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 21 bytes
[Tue Aug 16 00:12:04.292891 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): -App-Version: 0.2.3\r\n
[Tue Aug 16 00:12:04.292897 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:12:04.292921 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292925 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): D
[Tue Aug 16 00:12:04.292929 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.292941 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292944 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): D
[Tue Aug 16 00:12:04.292947 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 36 bytes
[Tue Aug 16 00:12:04.292950 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ate: Mon, 15 Aug 2022 15:12:04 GMT\r\n
[Tue Aug 16 00:12:04.292954 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:12:04.292957 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292960 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:12:04.292967 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.292971 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292975 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:12:04.292979 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 19 bytes
[Tue Aug 16 00:12:04.292983 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ontent-Length: 12\r\n
[Tue Aug 16 00:12:04.292988 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:12:04.292993 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.292997 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:12:04.293002 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.293007 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.293011 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): C
[Tue Aug 16 00:12:04.293016 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 40 bytes
[Tue Aug 16 00:12:04.293020 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): ontent-Type: text/plain; charset=utf-8\r\n
[Tue Aug 16 00:12:04.293025 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [speculative-blocking] 1 readbytes
[Tue Aug 16 00:12:04.293029 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.293034 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \r
[Tue Aug 16 00:12:04.293039 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.293049 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.293053 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \r
[Tue Aug 16 00:12:04.293058 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 1 bytes
[Tue Aug 16 00:12:04.293062 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): \n
[Tue Aug 16 00:12:04.293072 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [remote 127.0.0.1:8080] mod_dumpio: dumpio_in [readbytes-nonblocking] 12 readbytes
[Tue Aug 16 00:12:04.293078 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): 12 bytes
[Tue Aug 16 00:12:04.293082 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): Hello World\n
[Tue Aug 16 00:12:04.293112 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(164): [client 127.0.0.1:42654] mod_dumpio: dumpio_out
[Tue Aug 16 00:12:04.293120 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (data-HEAP): 194 bytes
[Tue Aug 16 00:12:04.293123 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (data-HEAP): HTTP/1.1 200 OK\r\nDate: Mon, 15 Aug 2022 15:12:04 GMT\r\nServer: Apache/2.4.41 (Ubuntu)\r\nX-App-Name: http-echo\r\nX-App-Version: 0.2.3\r\nContent-Length: 12\r\nContent-Type: text/plain; charset=utf-8\r\n\r\n
[Tue Aug 16 00:12:04.293133 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(164): [client 127.0.0.1:42654] mod_dumpio: dumpio_out
[Tue Aug 16 00:12:04.293137 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (data-HEAP): 12 bytes
[Tue Aug 16 00:12:04.293140 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (data-HEAP): Hello World\n
[Tue Aug 16 00:12:04.293143 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (metadata-EOS): 0 bytes
[Tue Aug 16 00:12:04.293173 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(164): [client 127.0.0.1:42654] mod_dumpio: dumpio_out
[Tue Aug 16 00:12:04.293178 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (metadata-EOR): 0 bytes
[Tue Aug 16 00:12:04.293199 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [speculative-nonblocking] 1 readbytes
[Tue Aug 16 00:12:04.293883 2022] [dumpio:trace7] [pid 6299:tid 140322755573504] mod_dumpio.c(135): [client 127.0.0.1:42654] mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Tue Aug 16 00:12:04.293900 2022] [dumpio:trace7] [pid 6299:tid 140322755573504] mod_dumpio.c(164): [client 127.0.0.1:42654] mod_dumpio: dumpio_out
[Tue Aug 16 00:12:04.293904 2022] [dumpio:trace7] [pid 6299:tid 140322755573504] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (metadata-FLUSH): 0 bytes
[Tue Aug 16 00:12:04.293908 2022] [dumpio:trace7] [pid 6299:tid 140322755573504] mod_dumpio.c(58): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (metadata-EOC): 0 bytes

よく見ると、HTTPレスポンスに関する内容が2回記録されています。

[Tue Aug 16 00:12:04.292822 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_in (data-HEAP): HTTP/1.1 200 OK\r\n


[Tue Aug 16 00:12:04.293123 2022] [dumpio:trace7] [pid 6299:tid 140322680039168] mod_dumpio.c(100): [client 127.0.0.1:42654] mod_dumpio:  dumpio_out (data-HEAP): HTTP/1.1 200 OK\r\nDate: Mon, 15 Aug 2022 15:12:04 GMT\r\nServer: Apache/2.4.41 (Ubuntu)\r\nX-App-Name: http-echo\r\nX-App-Version: 0.2.3\r\nContent-Length: 12\r\nContent-Type: text/plain; charset=utf-8\r\n\r\n

HTTPリクエストボディも2回記録されています。

[Tue Aug 16 00:10:08.469057 2022] [dumpio:trace7] [pid 6205:tid 140150201898752] mod_dumpio.c(100): [client 127.0.0.1:51742] mod_dumpio:  dumpio_in (data-HEAP): {"message": "logging request"}


[Tue Aug 16 00:10:08.469401 2022] [dumpio:trace7] [pid 6205:tid 140150201898752] mod_dumpio.c(100): [remote 127.0.0.1:8080] mod_dumpio:  dumpio_out (data-HEAP): {"message": "logging request"}

記録されている内容がDumpIOInputとDumpIOOutputのどちらが影響しているかは、ログに一緒に出力されているdumpio_inおよび
dumpio_outで確認できそうです。

これは、リバースプロキシとした場合は以下の状態になるみたいからみたいですね。

• DumpIOInput … Apache自身が受けたリクエストの内容＋バックエンドサーバーのレスポンスの内容（Apacheから見ると"入力"）
• DumpIOOutput … Apacheが返すレスポンスの内容＋バックエンドサーバーに送信するリクエストの内容（Apacheから見ると"出力"）

大量に出力されるので、このあたりの挙動は押さえておいた方がよさそうですね。

ここまで確認したら、Apacheを停止。

$ sudo systemctl stop apache2

nginxの場合

続いては、nginxです。

nginxの場合は単純で、ログフォーマットに$request_bodyを追加すればHTTPリクエストボディを記録することができます。

Ubuntu Linuxでインストールしたnginxのデフォルトのログフォーマットは以下のようになっているので、

/etc/nginx/nginx.conf

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

ここに$request_bodyを追加します。

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" "$request_body"';

このログフォーマットは、同ファイル内のすぐ近くでaccess_logディレクティブに適用されています。

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" "$request_body"';

    access_log  /var/log/nginx/access.log  main;

設定としては、このようにログフォーマットに追加するだけでHTTPリクエストボディがアクセスログに記録されるようになります。

ところで、この項目はlog_formatディレクティブには出てこないのですが

Module ngx_http_log_module / Directives / log_format

説明をよくよく見ると、「共通の変数」とログ出力時のみに使える変数が扱えるということなので

The log format can contain common variables, and variables that exist only at the time of a log write:

こちらの変数一覧からもある程度ログ出力には使えるということなのでしょう。

Alphabetical index of variables

$request_bodyの説明は、こちら。

Module ngx_http_core_module / Embedded Variables / $request_body

proxy_pass、fastcgi_pass、uwsgi_pass、scgi_passディレクティブによって処理される時に使えるみたいですね。

The variable’s value is made available in locations processed by the proxy_pass, fastcgi_pass, uwsgi_pass, and scgi_pass directives when the request body was read to a memory buffer.

今回リバースプロキシを構成しようとしているのは、ある意味では正解でした、と。

では、リバースプロキシの設定も行いましょう。

以下の設定を

/etc/nginx/conf.d/default.conf

    location / {
        root   /usr/share/nginx/html;
        index  index.html index.htm;
    }

このように変更。

    location / {
        proxy_pass http://localhost:8080;
    }

nginxを起動。

$ sudo systemctl restart nginx

リクエストを送信。

$ curl -XPOST localhost -d '{"message": "logging request"}'
Hello World

すると、アクセスログにHTTPリクエストボディが記録されるようになりました。

/var/log/nginx/access.log

127.0.0.1 - - [16/Aug/2022:01:18:10 +0900] "POST / HTTP/1.1" 200 12 "-" "curl/7.68.0" "-" "{\x22message\x22: \x22logging request\x22}"

Apacheのmod_dumpioでは記録できていたHTTPレスポンスボディは、nginxでは標準では記録できないようです。調べてみると、Luaスクリプトを
書くことになりそうですね。

その点は、今回は置いておきます。

やりたいことはできたので、今回はここまでということで。

まとめ

Apacheおよびnginxで、HTTPリクエストボディを記録する方法を調べてみました。

Apacheの場合は追加モジュールが必要になりますが、ものすごく大量に情報が記録されます…。
nginxの方は割と簡単ですね。

あまり使う機会はないと思いますし、適用しっぱなしにするような設定ではありませんが、覚えておくと役に立つことがあるかもしれません。