Spring SecurityのOAuth2サポートでKeycloak 19.0を使った認証を試す

Keycloak Spring

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

先日、WildFlyベースからQuarkusベースになったKeycloakをインストールしてKeycloak自体にログインするところまでやってみました。

Ubuntu Linux 20.04 LTSにKeycloak 19.0をインストールする - CLOVER🍀

今回は、Spring SecurityのOAuth2サポートを使ってKeycloakと連携してログインまで行ってみます。

環境

今回の環境は、こちら。

$ java --version
openjdk 17.0.4 2022-07-19
OpenJDK Runtime Environment (build 17.0.4+8-Ubuntu-120.04)
OpenJDK 64-Bit Server VM (build 17.0.4+8-Ubuntu-120.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.8.6 (84538c9988a25aec085021c365c560670ad80f63)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 17.0.4, vendor: Private Build, runtime: /usr/lib/jvm/java-17-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-124-generic", arch: "amd64", family: "unix"

Keycloakのバージョンはこちらで、172.17.0.2で動作しているものとします。

$ bin/kc.sh --version
Keycloak 19.0.1
JVM: 17.0.4 (Eclipse Adoptium OpenJDK 64-Bit Server VM 17.0.4+8)
OS: Linux 5.4.0-124-generic amd64

また、以下のコマンドで管理ユーザーは起動時に作成しておきます。

$ KEYCLOAK_ADMIN=admin KEYCLOAK_ADMIN_PASSWORD=password bin/kc.sh start-dev

お題

タイトルにも書いているとおりですが、Spring Securityを使って作成したアプリケーションのログインの確認のみを行います。
この時、ログインにはKeycloakを使います。

今回は認証のみで、認可には触れないことにします。また、ログアウトにも触れません。

Keycloakの準備

まずは、Keycloakの準備をしておきます。

以下の情報、手順で作成していきます。

Realm
- Realmの名前をsample-realmとして作成

特に、デフォルト設定から変更するところがわかるようにしたいと思います。

Client
- 作成時
  - Client IDをspring-security-clientに設定
  - Client authenticationをOnに設定
  - Direct access grantsのチェックボックスを外す
- 作成後
  - Settingsタブ
    - Root URLをhttp://localhost:8080に設定
    - Valid redirect URIsにhttp://localhost:8080/*を設定
    - 保存

また、CredentialsタブのClient secretの値を控えておきます。

User
- 作成時
  - Usernameをtest-userとして作成
- 作成後
  - Credentialsタブ
    - パスワードを設定
    - TemporaryをOffに設定
    - 保存

Spring Bootプロジェクトを作成する

次は、アプリケーションを作成していきます。

$ curl -s https://start.spring.io/starter.tgz \
  -d bootVersion=2.7.2 \
  -d javaVersion=17 \
  -d name=spring-security-oauth2-client-login-example \
  -d groupId=org.littlewings \
  -d artifactId=spring-security-oauth2-client-login-example \
  -d version=0.0.1-SNAPSHOT \
  -d packageName=org.littlewings.keycloak.spring \
  -d dependencies=web,oauth2-client \
  -d baseDir=spring-security-oauth2-client-login-example | tar zxvf -

プロジェクト内に移動。

$ cd spring-security-oauth2-client-login-example

Maven依存関係等は、こちら。

        <properties>
                <java.version>17</java.version>
        </properties>
        <dependencies>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-oauth2-client</artifactId>
                </dependency>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-web</artifactId>
                </dependency>

                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-test</artifactId>
                        <scope>test</scope>
                </dependency>
        </dependencies>

        <build>
                <plugins>
                        <plugin>
                                <groupId>org.springframework.boot</groupId>
                                <artifactId>spring-boot-maven-plugin</artifactId>
                        </plugin>
                </plugins>
        </build>

spring-boot-starter-oauth2-clientが含まれているのがポイントです。

生成されたソースコードは削除しておきます。

$ rm src/main/java/org/littlewings/keycloak/spring/SpringSecurityOauth2ClientLoginExampleApplication.java src/test/java/org/littlewings/keycloak/spring/SpringSecurityOauth2ClientLoginExampleApplicationTests.java

では、ソースコードを作成していきます。

まずはSpring SecurityのOAuth2サポートの設定。

src/main/java/org/littlewings/keycloak/spring/OAuth2ClientSecurityConfig.java

package org.littlewings.keycloak.spring;

import org.springframework.context.annotation.Bean;
import org.springframework.security.config.Customizer;
import org.springframework.security.config.annotation.web.builders.HttpSecurity;
import org.springframework.security.config.annotation.web.configuration.EnableWebSecurity;
import org.springframework.security.oauth2.client.registration.ClientRegistrationRepository;
import org.springframework.security.web.SecurityFilterChain;

@EnableWebSecurity
public class OAuth2ClientSecurityConfig {
    @Bean
    public SecurityFilterChain filterChain(HttpSecurity http, ClientRegistrationRepository clientRegistrationRepository) throws Exception {
        http
                .authorizeHttpRequests(authorize -> authorize
                        .mvcMatchers("/secure/**").authenticated()
                        .anyRequest().permitAll())
                .oauth2Login(Customizer.withDefaults())
                .logout(logout -> logout
                        .logoutUrl("/logout")
                        .logoutSuccessUrl("/"));

        return http.build();
    }
}

このあたりを参考に設定しました。

Authorize HttpServletRequests with AuthorizationFilter :: Spring Security

OAuth2 :: Spring Security

OAuth 2.0 Login :: Spring Security

Core Configuration :: Spring Security

/secure配下のURLは、ログイン必須とします。

RestController。

src/main/java/org/littlewings/keycloak/spring/SampleController.java

package org.littlewings.keycloak.spring;

import org.springframework.security.oauth2.client.authentication.OAuth2AuthenticationToken;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class SampleController {
    @GetMapping
    public String index() {
        return "Hello, Spring Security Application!!";
    }

    @GetMapping("token")
    public Object token(OAuth2AuthenticationToken authenticationToken) {
        return authenticationToken != null ? authenticationToken : "not login";
    }

    @GetMapping("secure/token")
    public OAuth2AuthenticationToken secureToken(OAuth2AuthenticationToken authenticationToken) {
        return authenticationToken;
    }
}

secureをパスに含まないエンドポイントは、ログインしていなくてもアクセスできることを前提にしています。

OAuth2AuthenticationTokenクラスは、Spring SecurityのOAuth2サポートにおける認証情報です。

OAuth2AuthenticationToken (spring-security-docs 5.7.2 API)

今回は、こちらをそのままクライアントに返すようにしています。

mainクラス。

src/main/java/org/littlewings/keycloak/spring/App.java

package org.littlewings.keycloak.spring;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class App {
    public static void main(String... args) {
        SpringApplication.run(App.class, args);
    }
}

あとは、設定ですね。

src/main/resources/application.properties

spring.security.oauth2.client.registration.keycloak.client-id=spring-security-client
spring.security.oauth2.client.registration.keycloak.client-secret=A3PoFLyrslGxxErrqJ4NALqpdOPsMmf8
spring.security.oauth2.client.registration.keycloak.client-name=spring security oauth2 login example
spring.security.oauth2.client.registration.keycloak.authorization-grant-type=authorization_code
spring.security.oauth2.client.registration.keycloak.scope=openid
spring.security.oauth2.client.registration.keycloak.redirect-uri={baseUrl}/login/oauth2/code/{registrationId}

spring.security.oauth2.client.provider.keycloak.authorization-uri=http://172.17.0.2:8080/realms/sample-realm/protocol/openid-connect/auth
spring.security.oauth2.client.provider.keycloak.token-uri=http://172.17.0.2:8080/realms/sample-realm/protocol/openid-connect/token
spring.security.oauth2.client.provider.keycloak.user-info-uri=http://172.17.0.2:8080/realms/sample-realm/protocol/openid-connect/userinfo
spring.security.oauth2.client.provider.keycloak.jwk-set-uri=http://172.17.0.2:8080/realms/sample-realm/protocol/openid-connect/certs
spring.security.oauth2.client.provider.keycloak.user-name-attribute=preferred_username

spring.jackson.serialization.indent_output=true

Spring Bootのドキュメントには、このあたりの情報はなさそうです。

spring.security.oauth2.client.provider. OAuth provider details. spring.security.oauth2.client.registration. OAuth client registrations.

Common Application Properties / Security Properties

OAuth 2.0のフローについては、認可コードフローを使うこととしてこのあたりを見つつ設定しました。

Authorization Grant Support :: Spring Security

Authorization Grant Support / Authorization Code

Web Application Security / / client-registration

Web Application Security / provider

Keycloakのエンドポイントは、こちらに記載があります。

Server Administration Guide / SSO protocols / OpenID Connect / Keycloak server OIDC URI endpoints

動作確認してみる

準備ができたので、動作確認してみましょう。

アプリケーションを起動します。

$ mvn spring-boot:run

http://localhost:8080/にアクセスしてみます。

http://localhost:8080/tokenにアクセスしてみます。

いずれも、ログインしていなくてもアクセスできます。後者は、情報が出力されませんが。

http://localhost:8080/secure/tokenにアクセスすると、ログインが必要なのでKeycloakにリダイレクトされます。

ユーザー名とパスワードを入力して、ログイン。

ログインが成功すると、http://localhost:8080/secure/tokenにリダイレクトされ、今度はユーザーの情報などが表示されます。

ログインしているので、http://localhost:8080/tokenにアクセスすると先ほどと挙動が変わり、http://localhost:8080/secure/tokenと同じ内容が
表示されます。

OKですね。

ちなみに、今の設定でhttp://localhost:8080/logoutにアクセスするとログアウト画面に遷移しますが、

ここでログアウトしてもアプリケーション側からログインするだけなので、http://localhost:8080/secure/tokenにアクセスするとKeycloakに
リダイレクトしつつKeycloak側ではログインしたままなので即座にログイン済みの状態になります。

このあたりは、また今度追うとしましょう。

まとめ

Spring SecurityのOAuth2サポートとKeycloakを使って、認証だけ試してみました。

認可やログアウトなどもっといろいろ見たいのですが、ちょっと大変になりそうだったので少しずつ見ていくことにしました。

ゆっくりやっていきましょう。

2022-08-16

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

Apache nginx Linux

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

デバッグ等で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の方は割と簡単ですね。

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