TCPパケットを解析して構造化ログでダンプするツール tcpdp を作った

Golang

やっと形になってきました。

github.com

「データベースのクエリログを取得したい」

例えば、データベース（RDBMS）のクエリログを取得したいとき一番確実な方法は、そのRDBMSに備わっているログ機構を利用することです。

一方で、全てのクエリログを出力するとなるとそれなりにIO負荷がかかることが予想されるので、負荷状況によってはクエリログ出力（のIO負荷）を別サーバに分離したくなります。

では、どうすればよいかというと、例えば

  • アプリケーションサーバとデータベースサーバの間にプロキシサーバを挟んでそこで記録することでIO負荷を分離する
  • アプリケーションサーバ側で（notアプリケーションで）記録することで（大抵、サーバ台数の多い）アプリケーション側にIO負荷を分散する

というような方法を思いつきます。

そこで、「もし、TCPコネクション上に流れている（例えば）クエリログを解析してログ出力ができれば利用できるシチュエーションがあるのでは？」というアイデアからPoCとして作成しはじめたのがtcpdpです

嘘です。

とりあえずTCP Proxyを作ってみてクエリ見えたりしないかな？と作り始めたのが本当です。

ちなみに開発当初tcprxyという名前だったのですが、機能が拡張された結果、TCP Proxyだけではなくなったので名称を変更しました。

tcpdp

tcpdpは、TCPパケットを解析して構造化ログとして出力するツールです。

tcpdpには以下のような特徴があります。

  • 対応しているプロトコルであればTCPパケットを解析して、構造化ログとして出力可能
    • 現在MySQLのクエリとPostgreSQLのクエリに対応。hexdumpのように解析せずに構造化ログを出力する機能もある。
  • TCPパケットの取得方法を選択可能
    • TCPプロキシサーバ
    • ネットワークインターフェースをキャプチャ
    • pcap形式のファイル読み込み
  • 構造化ログのフォーマットはJSONとLTSVに対応

インストール

go get でインストールします。

また、libpcapをつかいますので、例えばUbuntuだと libpcap-dev のインストールが必要になります。

$ go get github.com/k1LoW/tcpdp

使い方

tcpdpは「TCPパケットを解析して出力する」という点は同じで、動きが異なる3つのモード（コマンド）があります。

  1. TCPプロキシサーバとして起動する ( tcpdp proxy )
  2. tcpdumpのようにネットワークインターフェースのパケットをキャプチャするサーバとして起動する ( tcpdp probe )
  3. pcapファイルを読んで構造化フォーマットで出力する ( tcpdp read )

1. TCPプロキシサーバとして起動する ( tcpdp proxy )

tcpdpはTCPプロキシサーバとして起動できます。

$ tcpdp proxy -l localhost:55432 -r db.internal.example.com:5432 -d pg

上記のコマンドでは、55432ポートで待ち受けて、db.internal.example.com:5432 とのTCPプロキシとして稼働しつつ、TCPパケットからPostgreSQLのクエリログを解析し以下のような構造化ログとして出力します。

{"ts":"2018-09-22T14:23:46.845+0900","src_addr":"127.0.0.1:50736","dst_addr":"127.0.0.1:54322","query":"SELECT * FROM information_schema.tables;","message_type":"Q","conn_id":"bekn7iroo3smcklg5rf0","username":"postgres","database":"testdb"}
{"ts":"2018-09-22T14:23:46.847+0900","src_addr":"127.0.0.1:50736","dst_addr":"127.0.0.1:54322","stmt_name":"","parse_query":"SELECT CONCAT($1::text, $2::text, $3::text);","message_type":"P","conn_id":"bekn7iroo3smcklg5rf0","username":"postgres","database":"testdb"}
{"ts":"2018-09-22T14:23:46.847+0900","src_addr":"127.0.0.1:50736","dst_addr":"127.0.0.1:54322","portal_name":"","stmt_name":"","bind_values":["012345679","あいうえおかきくけこ",""],"message_type":"B","conn_id":"bekn7iroo3smcklg5rf0","username":"postgres","database":"testdb"}

また、TERM を受け取ってGraceful Shutdownするようにしているので、以下のようにlestrrat-go/server-starterと連携してhot-deployも可能になっています。

$ start_server --port 33306 -- tcpdp proxy -s -r db.example.com:3306 -d mysql

ログはuber-go/zapとlestrrat-go/file-rotatelogsを利用して、サーバログ(tcpdp.log)と解析結果のダンプログ(dump.log)を構造化ログとして（ログローテーション対応で）出力するようになっています。

設定ファイルは(後述する tcpdp probe も含めて）以下のように記述して指定可能です。

[tcpdp]
pidfile = "/var/run/tcpdp.pid"     # pid ファイルの場所
dumper = "mysql"                       # 解析方法（dumper）

[probe]
target = "db.example.com:3306"
interface = "en0"

[proxy]
useServerSterter = false # server-starter を利用するかどうか
listenAddr = "localhost:3306"
remoteAddr = "db.example.com:3306"

[log]
dir = "/var/log/tcpdp" # サーバログ
enable = true # サーバログを出力するか
stdout = true # ログをstdoutに出力するか
format = "ltsv" # ログフォーマット ( JSON or LTSV )
rotateEnable = true # ログローテートの有効化
rotationTime = "daily" # ローテーション間隔
rotationCount = 7 # ローテーションファイル数

[dumpLog]
dir = "/var/log/dump" # ダンプログ
enable = true
stdout = false
format = "json"
rotateEnable = true
rotationTime = "hourly"
rotationCount = 24

2. tcpdumpのようにネットワークインターフェースのパケットをキャプチャするサーバとして起動する ( tcpdp probe )

TCPプロキシサーバを立てるということは、それなりに既存のシステム構成に変更が入ります。

構成変更が難しい場合や、「実際にどのようなログが取得できるのか」「そもそも取得できるのか」といった検証にも使えるのが tcpdp probe です。

「tcpdumpのように」というのが使い方のイメージほぼ全てで、以下のようにネットワークインターフェースを指定してパケットをキャプチャして構造化ログを出力できます。

$ sudo tcpdp probe -i eth0 -t 3306 -d mysql # `tcpdump -i eth0 tcp port 3306` と同じようなBPFの指定

（なお、v0.8.0 時点で tcpdp probe はGraceful Shutdownやserver-starter等への対応ができていないので注意が必要です。）

3. pcapファイルを読んで構造化フォーマットで出力する ( tcpdp read )

「そもそもtcpdumpにはpcapファイル出力機能があるしログローテート機能もある。パケットキャプチャという意味ではtcpdumpのほうが信頼できる」

ということに気づいて作ってみたのが tcpdp read です。

以下のようにファイル保存したpcapファイルを読み込んで構造化フォーマットでSTDOUTに出力できます。

$ sudo tcpdump -i eth0 host 127.0.0.1 and tcp port 3306 -w mysql.pcap
[しばらくキャプチャしてからtcpdumpを終了させる]
$ tcpdp read mysql.pcap -d mysql -t 3306 -f json

tcpdpが保存するログよりもファイルサイズは大きくなりますが、確実にログを残すという意味ではpcapをログとして保存もアリだと考えています。

解析できるプロトコル

現在力をいれて開発しているプロトコル解析エンジン（dumperと呼んでいます）は、MySQLのクエリログとPostgreSQLのクエリログです。

MITMな機能は入れていないのでプレーンなテキストでの通信しか解析できませんが、MySQLもPostgreSQLもクエリの取得はできるようになっています。

tcpdpの今後

当初のモチベーションは、上記に書いたように「データベースのクエリログを取得すること」でした。

しかし、実装を進めていくにつれて「TCPのパケットをヒトが読めるように解析して構造化ログとして出力する」というのは汎用的なツールとして使いどころがありそうだなと感じています（インフラ強者の人たちはパケットをそのまま読むらしいですが）。

とりあえず、今後のTODOとして以下のようなことを考えています。

  • プロトコル解析エンジン（dumper）をプラグインとして組み込めるようにしたい
    • そのために、まず内部構造のアーキテクチャを納得できるところまで綺麗にしたい
  • HTTPプロトコルを解析できるようにしたい
    • 「ISUCONベンチーマークのHTTPリクエストをキャプチャしてcurlコマンドに変換する」とか考えがち

使いどころがないとしても個人的には今まで興味も示さなかった、いわゆるL4（トランスポート層）の領域に手を出してみて、とても勉強になっています。

MySQLとPostgreSQLのプロトコルの比較とか、なかなかない体験で面白いです。

というわけで

もし良ければ触ってみてください！

あと、こういうTCPとかMySQL/PostgreSQLのプロトコルとかの解釈の話をどこかで話してフィードバックをもらいたいのですが、いったいどこで話したら。。。。