auditdのログをlogrotateでローテートする運用にしたかったがうまくいかなかったのでcronで直接ローテートするようにした

紆余曲折の記録です。

Auditとは何か

Linux AuditはLinuxのシステムで発生しているイベントを記録するための仕組みです。詳しくは以下のページ

第5章 システム監査 - Red Hat Customer Portal

具体的には、(デフォルトで) /var/log/audit/audit.logシステムコールやユーザが実行したコマンドなどの様々なシステムイベントを記録するサービス auditd が起動することになります。

auditdのログ (audit.log) を長期保存したい

audit.logはそのまま監査ログとして利用できるため、一定期間保存しようと考えます。

しかし、前述のようにauditdは様々なシステムイベントを記録するために単純にログの保存を続けるとかなりのディスク容量を消費していきます。

そのためログローテーションの設定を組むのが一般的であり、それ以前にauditd自体にはログローテーションの機構が備わっており、デフォルトで有効になっています。

しかし、そのままローテートをしていると端から消えていくことになるので、ローテートされた古いログを保存する仕組みが必要になります。

あわせて、以下の3つの要件を実現しようと考えました。

  1. 時間ベースでローテートをしたい
    • あとでログを見つけやすくするため。ログローテートされたaudit.logに時刻のプレフィックス (ex. audit.log-2018111115 ) をつけたい
  2. ローテーション時に圧縮して保存したい
    • ログファイルが大きくなりがちのため
  3. audit.logのみで保存したい

ぱっと見、logrotateに任せたほうが良さそうです(しかし、後述しますが失敗しました)

logrotateの前に検討したいくつかの方法

auditd の設定でなんとかする

auditd.confの設定パラメータを見る限りでは時間ベースのローテートの仕組みや古いログを圧縮するためのフック機構などはなさそうでした。

audisp pluginを利用してsyslogに記録する

audisp pluginを利用して、auditdのログをsyslogに記録して、syslogに設定したログローテーションにのっかるという方法があります。

  • auditd.conf で dispatcher = /sbin/audispd を指定
  • /etc/audisp/plugins.d/syslog.conf を有効化
active = yes
direction = out
path = builtin_syslog
type = builtin
args = LOG_INFO
format = string

これでsyslogがlogrotateでログローテートされてれば、合わせてaudit.logの情報もローテートされるという仕掛けです。

しかし、今回はaudit.logのみで保存をしたいのとsyslogにもよく参照する情報があって混在するのを避けたかったため、この方法は見送ることにしました。

audit.logを直接logrotateの仕組みに載せる -> 失敗

これが本命 ですでした。

auditdが独自にログローテーション機能を止めてlogrotateの仕組みに載せることができれば、「時間ベースのローテーション」も「古いログの圧縮保存」も「audit.logのみでのローテーション」も実現できると考えました。

まず、/etc/audit/auditd.conf の max_log_file_action の設定を変更して auditdのログローテーションを止めます。

max_log_file_action = IGNORE

そしてlogrotateの設定を追加します。

   /var/log/audit/audit.log
    {
      rotate 24
      hourly
      ifempty
      dateext
      missingok
      compress
      delaycompress
    }

これでauditdを再起動して、確認しましたが 結果、うまくいきませんでした

ログファイルはローテートするのですが、auditdが audit.log ではなく、ローテートしたほうの audit.log-2018111115 の方にそのままログを書き続けてしまいました。

原因は、auditdが最初に掴んだログファイルのファイルディスクリプタにそのまま書き込んでいるからだと予想できます。

ちなみに、logrotateで考えるべきことについては @catatsuy さんの以下のエントリがとてもわかりやすかったです。

medium.com

ここまでで、auditdは上記エントリで示されている「ちゃんとローテートをしたい場合」の3つの方法のうちの 「1. ファイルに書き込む度にファイルをopenして書き込み後にcloseする」という挙動にも「3. ファイル名が変更されたタイミングを自力で検知して、元のファイル名でopenし直す」 という挙動にもなっていないということがわかりました。

なので、最後に残った「2. ファイル名が変更されたタイミングを教えてもらい、元のファイル名でopenし直す」方法を考えてみました。

しかし、auditdにはNGINXのUSR1のような「元のファイル名でopenし直す」ようなシグナルは用意されておらず、これも断念することになりました。おそらくauditd自体がログローテーションの仕組みを持っているので、そのようなシグナルを受け取る処理を作る必要がなかったのではないか?と予想しました。

logrotateで、ファイルディスクリプタを掴むようなプロセスのときに使うらしい copytruncate オプションを付与すれば一見うまくいくのですが、ログファイルをコピーして(copy)元のファイルの内容を消去する(truncate)するときにログを一部ロストしてしまう可能性があるということで(監査ログという意味でも)選択できませんでした。

cronで直接ローテートするようなスクリプトを組む

というわけでlogrotateの仕組みに載せるのはあきらめて、直接cronをトリガーに意図したログローテーションをするようにスクリプトを組みました。

#!/bin/bash

set -eu

DATEEXT=`date +%Y%m%d%H`
KEEP=5
[ -f /var/run/auditd.pid ] && kill -USR1 `cat /var/run/auditd.pid`
[ -f /var/log/audit/audit.log.1 ] && mv /var/log/audit/audit.log.1 /var/log/audit/audit.log-${DATEEXT}
[ -f /var/log/audit/audit.log-${DATEEXT} ] && gzip -f /var/log/audit/audit.log-${DATEEXT}
ls -t /var/app/audit.log-* | tail -n+${KEEP} | xargs --no-run-if-empty -i mv {} /backup/'

仕組みとしては以下のページの方法と同じです。

How to implement audit log rotation with compression based on time instead of size - Red Hat Customer Portal

  1. まずUSR1シグナルをauditdプロセスに渡すことで、auditdのログローテーション機能を実行します。
  2. 生成された audit.log.1 を時刻つきファイル名にリネームします
  3. 2でリネームしたファイルをgzipで圧縮します
  4. 古いログファイルから移動します

上記スクリプトをcronで1時間ごとに実行することで、なんとかやりたいことを実現することができました。

結局

audit.logを時間でローテートするベストな方法は何だったのか。。是非どなたか教えて欲しいです。

ここまでくるのに時間がかかってしまった。。

Fukuoka.go#12 で GoでTCPパケットを読むための最初の一歩の話 をした #fukuokago

Fukuoka.go に参加してきました!

fukuokago.connpass.com

主催者、発表者のみなさん、ありがとうございました!

ちょっとトラブルがあって楽しみにしていた「Road to your goroutines」をまともに聞けなかったので残念がっていたら、素晴らしいまとめエントリが上がっていて本当に感謝です!!

GoでTCPパケットを読む

最近、tcpdpというTCPパケットを読むツールを作っているのですが、その開発をするにあたって「Goもやっぱりライブラリが揃っているな」と感じたので、そういった意味での発表をしました。

tcpdpの話をすると、プロトコルの解析苦労話になりそうだったのでやめときました(Goっぽくない)

google/gopacket

スライドを見てもらったらわかるとおり、ほとんど google/gopacket の紹介みたいになっています。

それでも、あまりにも簡単にtcpdumpぽいものが作れてしまうので、最初、個人的には本当にびっくりしました。

発表で作った簡易tcpdumpはわずか32行です。

package main

import (
  "encoding/hex"
  "fmt"
  "log"

  "github.com/google/gopacket"
  "github.com/google/gopacket/pcap"
)

func main() {
  device := "en0"
  filter := "tcp and port 80"

  handle, err := pcap.OpenLive(
    device, int32(0xFFFF), true, pcap.BlockForever,
  )
  if err != nil {
    log.Fatal(err)
  }
  defer handle.Close()
  if err := handle.SetBPFFilter(filter); err != nil {
    log.Fatal(err)
  }

  packetSource := gopacket.NewPacketSource(handle, handle.LinkType())
  for packet := range packetSource.Packets() {
    fmt.Printf("%s\n", packet)
    fmt.Printf("%s", hex.Dump(packet.Data()))
  }
}

たったこれだけで動くtcpdumpっぽいコマンドが出来上がりです。

そうするとあとは、拡張したいと思ったところをいじればいいし、気になるところはコードから定義ジャンプをしていけば理解が深まります。

書いて動くと理解が進む

発表資料をみたらわかるように、自分はネットワーク周辺は雰囲気で触っていることが多いです(注意: 上記ツイートはわざと面白おかしくしてもらった結果です)

しかし、実際にコードに落とし込んで動くようになると、次の試行錯誤をすることができます。

試行錯誤ができるところまでできたら、次の「使えるツールが作れるかも」というモチベーションを持った開発ができます。

モチベーションを持てるとちょっとばかり面倒な部分についても調べたり検証したりする気になります。

そして、結果として周辺の理解が進むと感じています。

というわけで

今回の発表で、自分と同じように「ネットワーク周り得意じゃないな」と思っている人がちょっとでも「Goで書けるならやってみようかな」と思ってくれたら幸いです。

そういえば、今週末もずっと []byte{} を眺めてたな。。。

pprofでCPU100%になる原因を特定する

tcpdpのprobeモードで、CPUが100%に張り付くという問題(結果、原因としてはしょうもないミス)がありました。

機能としては正しく動いているので、単純にテストケースを増やしてもどうにもならず、pprofを使って原因となっている箇所を絞り込んでみました。

本エントリはその記録です。なお、原因特定の問題としてはおそらく初級レベルだと思います(わからない)。

現状把握

tcpdp probetcpdump のようにインターフェースに流れるパケットをキャプチャするコマンドです。

ところが、以下のように実行したら、まだパケットを流していないのにCPUが100%に張り付きます。

$ sudo tcpdp probe -c t.toml
Password:
2018-09-30T00:40:42.199+0900    info    Starting probe. interface: lo0, target: 33306
2018-09-30T00:40:42.201+0900    info    Select dumper mysql.
$ sudo ps au
USER    PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
root  69915 100.3  0.2  4402600  36692 s003  R+   12:14AM   5:17.36 ./tcpdp probe -c t.toml
root  43796   0.3  0.1  4405812   8708 s002  S+   10:44PM   0:25.13 ./tcpdp probe -c t.toml
[...]

net/http/pprof を設置する

とりあえず net/http/pprof を設置します。

$ git diff
diff --git a/main.go b/main.go
index bc38d4c..2a0119b 100644
--- a/main.go
+++ b/main.go
@@ -20,8 +20,19 @@

 package main

-import "github.com/k1LoW/tcpdp/cmd"
+import (
+       "log"
+       "net/http"
+       _ "net/http/pprof"
+       "runtime"
+
+       "github.com/k1LoW/tcpdp/cmd"
+)

 func main() {
+       runtime.SetBlockProfileRate(1)
+       go func() {
+               log.Println(http.ListenAndServe("0.0.0.0:6060", nil))
+       }()
        cmd.Execute()
 }

参考URL

golang の net/http/pprof を触ってみたメモ - sonots:blog

go tool pprof でCPUのプロファイルを見る

net/http/pprof を設置したので、もう一度 tcpdp probe を実行します。そうすると http://localhost:6060/debug/pprof/ でプロファイル情報のページが生成されます。

そのプロファイルページに go tool pprof でアタッチして、CPUのプロファイルを見てみます。

localhost:6060 で起動している pprof のプロファイルページの /debug/pprof/profilego tool pprof でアタッチして、top で確認してみます。

$ go tool pprof -seconds 5 http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /Users/k1low/pprof/pprof.samples.cpu.007.pb.gz
Type: cpu
Time: Sep 29, 2018 at 12:54am (JST)
Duration: 5.14s, Total samples = 4.40s (85.59%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3870ms, 87.95% of 4400ms total
Dropped 10 nodes (cum <= 22ms)
Showing top 10 nodes out of 21
      flat  flat%   sum%        cum   cum%
    1440ms 32.73% 32.73%     3550ms 80.68%  runtime.selectgo 👈
     480ms 10.91% 43.64%      480ms 10.91%  runtime.unlock
     450ms 10.23% 53.86%      450ms 10.23%  runtime.lock
     360ms  8.18% 62.05%      360ms  8.18%  runtime.cputicks
     240ms  5.45% 67.50%      720ms 16.36%  runtime.selunlock
     240ms  5.45% 72.95%      240ms  5.45%  sync.(*Mutex).Unlock
     220ms  5.00% 77.95%      220ms  5.00%  sync.(*Mutex).Lock
     160ms  3.64% 81.59%      160ms  3.64%  runtime.(*hchan).sortkey (inline)
     140ms  3.18% 84.77%     4350ms 98.86%  github.com/k1LoW/tcpdp/reader.(*PacketReader).ReadAndDump 👈
     140ms  3.18% 87.95%      140ms  3.18%  runtime.duffzero

あああ、、、もう特定できてしましましたね。

runtime.selectgo が実行時間 (flat)では多いですが、関数内の呼び出しを含めた実行時間 (cum) をみると github.com/k1LoW/tcpdp/reader.(*PacketReader).ReadAndDump が支配的です。

この関数の中で何かをやらかしているのは明白です。

参考URL

Go pprof 入門編 (CPU Profile とコマンドラインツール) : KLabGames Tech Blog

go tool pprof -http を使ってWebUI上でグラフで確認する

ここで終わってもそっけないので、今度は pprof の WebUIを使ってグラフで確認してみます。

localhost:6060 で起動している pprof のプロファイルページにアタッチして 8888 で pprof の WebUIを立ち上げます。

$ go tool pprof -http=":8888" localhost:6060

するとWebページが開いて、グラフを確認することができます。

f:id:k1LoW:20180930121902p:plain

あああ、ReadAndDumpさん。。。

参考URL

Go 1.10でGolangのプロファイリングツール pprof のWebUIが入った話 - Keepdata Blog

go-torch を使ってFlame Graphで確認する

懲りずにさらに、go-torch を使ってFlame Graphで確認してみます。

まず、準備として go-torch と FlameGraph を落としておきます。

$ go get github.com/uber/go-torch
$ git clone https://github.com/brendangregg/FlameGraph

localhost:6060 で起動している pprof のプロファイルページにアタッチしてFlame Graphのsvgファイルを生成します。

$ PATH=$PATH:/path/to/FlameGraph go-torch --time 5 --url http://localhost:6060/debug/pprof/profile

f:id:k1LoW:20180930122026p:plain

。。。。ReadAndDumpで決定ですね。

参考URL

GolangでFlame Graphを描く | SOTA

原因特定

原因はReadAndDumpで実行しているforの中のselect句で、「何もしないdefault:が存在している」ことで、ビジーループになっていたことでした。しょうもないバグ。

default: を取り除き、最終的にpprof のプロファイル結果も以下のようにスッキリしました。

$ go tool pprof -seconds 5 http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /Users/k1low/pprof/pprof.samples.cpu.013.pb.gz
Type: cpu
Time: Sep 29, 2018 at 2:27am (JST)
Duration: 5s, Total samples = 20ms (  0.4%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 20ms, 100% of 20ms total
      flat  flat%   sum%        cum   cum%
      20ms   100%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).getNextBufPtrLocked.func1
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket.(*PacketSource).NextPacket
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket.(*PacketSource).packetsToChannel
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).ReadPacketData
         0     0%   100%       20ms   100%  github.com/k1LoW/tcpdp/vendor/github.com/google/gopacket/pcap.(*Handle).getNextBufPtrLocked

f:id:k1LoW:20180930122104p:plain

該当の修正Pull Requestはこちら

まとめ

今回はpprofを使ってCPU100%張り付きの原因特定をしてみました。

自分は、こういう「計測」には慣れていないので、これからも素振りをしていこうと思います。

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

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

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/zaplestrrat-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な機能は入れていないのでプレーンなテキストでの通信しか解析できませんが、MySQLPostgreSQLもクエリの取得はできるようになっています。

tcpdpの今後

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

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

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

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

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

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

というわけで

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

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

ISUCON8に参加してほとんど何もできなかった

ISUCON8 予選に参加してきました。

自分個人としては、「ほとんど何もできなかった」という感想でした。

どうせ普段できないことは出来ない

どうせ普段できないことは出来ないと思って ( ISUCON8に参加した | | pyama.fun )

これは、本当にそのとおりでした。

チームメンバーのインフラ構成変更に対する手の速さはすごかったです。

一方、自分はというと

  • ソースコードは流石に読めたし修正もできた
  • ボトルネックの特定方法が雑すぎる
  • 慌てて、(普段はしっかり見るくせに)データベース設計を落ち着いて見るということをしなかった
  • 慌てて、短絡的な手しか打てない
  • 修正の手が遅い。トライアンドエラーが多すぎる

普段通り過ぎて、ため息しかないです。

そしてそれは障害対応のときに(チームメンバーと比べて)自分に感じている「遅い感」「冴えてない感」と同じでした。

なんというか、今まで鍛えていない別の筋肉を使っている感覚。

「普段できるように」鍛えないと駄目ですね。そして、せっかくそれを鍛えられる環境にはいるので「活用していかないと」と思いました。

参加してみて

いつの間にか参加することになって、結果、いろいろ足りないところを実感できました。

P山さんの誘い(というか申し込み)がなければ、参加しなかったし、実感できなかったことです。あと、集中モードのメンバーを間近で見れてよかったです。

とりあえず「普段できるように」なっていこうと思います。

net/http/pprof のheapの値は何を表しているのか

tcprxyというTCPプロキシを作っています。

github.com

8月中旬くらいから「よし、プロダクションレディになるくらいまで開発してやろう」と、時間を見つけては設定ファイルを読めるようにしたり、server_starterと連携できるようにしたり、取得できる情報の充実を図ったりしていました。いろいろ機能を追加してみたのですがそれはまたの機会に。

そして、「あとは、常時起動していてメモリリークが発生しないことを確認すればよいだろう」と、とりあえず見よう見まねで net/http/pprof を使ってブラウザ上からプロファイルを確認してみました。

具体的には main.go を以下のように修正して、tcprxy経由でMySQLに対してmysqlslapを使ってクエリを投げていました。mysqlslap <-> tcprxy <-> MySQL という感じです。

diff --git a/main.go b/main.go
index 56f4e32..5689432 100644
--- a/main.go
+++ b/main.go
@@ -20,8 +20,16 @@

 package main

-import "github.com/k1LoW/tcprxy/cmd"
+import (
+       "net/http"
+       _ "net/http/pprof"
+
+       "github.com/k1LoW/tcprxy/cmd"
+)

 func main() {
+       go func() {
+               http.ListenAndServe("localhost:6060", nil)
+       }()
        cmd.Execute()
 }

ところが、 http://localhost:6060/debug/pprof/ に表示されている値を眺めていると、

あれ、heapの値が増え続ける

goroutineの値はMySQLへの通信がなくなると元の値に戻るのに、heapの値だけが増え続けています。

自分がわからないところでメモリリークが起こっているの?

計測してみる

と思ったのでとりあえず計測してみました。

go version

> go version
go version go1.10.2 darwin/amd64

計測コード

for i in {1..1000} ; do
    echo "Do ${i}"
    mysqlslap \
  --no-defaults \
  --concurrency=50 \
  --iterations=10 \
  --engine=innodb \
  --auto-generate-sql \
  --auto-generate-sql-add-autoincrement \
  --auto-generate-sql-load-type=mixed \
  --auto-generate-sql-write-number=100 \
  --number-of-queries=1000 \
  --host=127.0.0.1 \
  --port=3306 \
  --user=root \
  --password=mypass \
  --ssl-mode=DISABLED >> heap.dump
    sleep 2
    curl -s http://localhost:6060/debug/pprof/ >> heap.dump
    curl -s http://localhost:6060/debug/pprof/heap?debug=1 >> heap.dump
done

tcprxy越しにmysqlslapで連続して通信をします。sleepを挟むことでTCPプロキシにおける接続数を一旦0にして、そのときのheapの情報を都度記録していきます。

実行時間としては一晩くらいかかりました。

計測結果

img

"pprof heap count (http://localhost:6060/debug/pprof/ に表示されているheapの値)" は明らかに増え続けています。

しかし"HeapSys"や"HeapAlloc"などその他の値にはその傾向はありません。

ソースコードを読んでみる

net/http/pprof からソースを追ってみました。

まず、src/runtime/pprof/pprof.go の countHeap()http://localhost:6060/debug/pprof/ に表示されているheapの値 のようです。

// countHeap returns the number of records in the heap profile.
func countHeap() int {
  n, _ := runtime.MemProfile(nil, true)
  return n
}

上記コードのように、runtime.MemProfile() の返り値を表示しているみたいです。

runtime.Memprofile

https://golang.org/pkg/runtime/#MemProfile

runtime.MemProfileのgodocを読むと

MemProfile returns a profile of memory allocated and freed per allocation site.

allocated and freed ということは開放された割り当てメモリも返すようです。

MemProfile returns n, the number of records in the current memory profile. If len(p) >= n, MemProfile copies the profile into p and returns n, true. If len(p) < n, MemProfile does not change p and returns n, false.

countHeap()ではruntime.MemProfileの第1引数の []MemProfileRecordnil なので、常にそのときの割り当てプロファイルの数を返すようです。

countHeap()ではruntime.MemProfileの第2引数の inuseZerotrue なので

If inuseZero is true, the profile includes allocation records where r.AllocBytes > 0 but r.AllocBytes == r.FreeBytes. These are sites where memory was allocated, but it has all been released back to the runtime.

ということで、割り当てプロファイルの数にはランタイムにリリースされた分も含むようです。

mbuckets

runtime.MemProfile のコードを追うと mbuckets の数をカウントしています。

mbuckets*runtime.bucket というコールスタックごとのプロファイリング情報の構造体で mbucktes はメモリ用のプロファイリング情報をもっている形になります。

以下は src/runtime/mprof.go からの抜粋

type bucket struct {
  next    *bucket
  allnext *bucket
  typ     bucketType // memBucket or blockBucket (includes mutexProfile)
  hash    uintptr
  size    uintptr
  nstk    uintptr
}

個人的に面白かったのが、プロファイリング情報群をsliceか配列かで持っているのかな?と思っていたら、そうではなくて next に次の bucket をポインタで保持しているということです。

そういうものなんですね。The representation is a bit sleazy, inherited from C. とコメントに書いてありました。

mbuckets はsrc/runtime/mprof.goの mProf_Malloc() -> stkbucket() で必要に応じて追加されるみたいです。

mbuckets を減らす処理は見つけられませんでした。

なぜ、計測回数を増やすごとにプロファイルの情報の数が増えるのか?

結論から言うとまだわかっていません。

src/runtime/mprof.go の stkbucket() のコードを読むと、bucketを保持するハッシュテーブルのサイズには上限(buckHashSize)があるようです。

そして、必要に応じて(同じプロファイル情報であれば?)再利用もされています。(以下は、sktbucket()のコードを抜粋)

  i := int(h % buckHashSize)
  for b := buckhash[i]; b != nil; b = b.next {
    if b.typ == typ && b.hash == h && b.size == size && eqslice(b.stk(), stk) {
      return b
    }
  }

  if !alloc {
    return nil
  }

  // Create new bucket.
  b := newBucket(typ, len(stk))

ただ、同じ処理(mysqlsrap)を繰り返しているのに、計測回数を増やすごとにプロファイルの情報が増えるというところがしっくりきていないところです(計測回数対しての線形増加なら「毎回新規でプロファイルを記録するんだな」とわかるのですが)。

計測結果を保存したheap.dumpにその記録されたプロファイル情報の詳細が残っているので、次回、そこから調べてみようと思っています。

まとめ

  • 計測してみた結果、「http://localhost:6060/debug/pprof/ に表示されているheapの値が増える = メモリリークが発生している」ということではないことがわかった。
  • http://localhost:6060/debug/pprof/ に表示されているheapの値はメモリ割り当てのタイミングで必要に応じて追加されるプロファイルの情報の数であることがわかった。
    • そしてその中にはすでに開放されているものも含まれているということもわかった。
  • 「なぜ、計測回数を増やすごとにプロファイルの情報の数が増えるのか」はわからなかった。

とりあえず、tcprxyにメモリリークがなさそうであることはわかったので良かったです。

go.uber.org/zapでコンソールとファイルのそれぞれに別々のフォーマットでログを出力する

夏休みの自由課題です。

今作っているサーバにログ出力の機能をつけたいと思っていて、ログライブラリを検討していました。

必要な要件は以下です。

  • ファイルには、構造化ログを出力したい(JSONでもLTSVでもなんでもいい)
  • コンソール(STDOUT)には、人間にある程度見やすいログを出力したい(色がつく必要はない)
    • ファイルログとコンソールログの情報は一緒で良い。見え方を変えたいだけ

複数の io.Writer に同時に出力するというところでは io.MultiWriter が思いつくのですが、 io.MultiWriter では io.Stdout とファイルに同時に出力することはできても、別のフォーマットにはできません。

実は、最初に採用しようと考えていたログライブラリでもいろいろ試行錯誤したのですが、そのライブラリでの解決方法は見つけられませんでした。

で、結局、zap というLoggerで綺麗に解決できたので紹介します。

zap

github.com

Goの世界ではとても有名なLoggerなのですね。高速というのも魅力です。

ちなみにzapの使い方や設定の説明は以下のエントリが最高です。

qiita.com

io.Stdoutとファイルのそれぞれに別々のフォーマットでログを出力する

上のエントリにもあるように普通のzapの使い方だと zap.Config を作成-> Build() して zap.Logger を作るのですが、今回は面倒なことをするので、zap.New() を利用して zap.Logger を作成します。

zap.New()zapcore.Core を引数に必要としますので、まずはzapcore.Core を作成します。

zapcore.Corezapcore.NewCore() を使って作成します。

zapcore.NewCore() は、zapcore.Encoderzapcore.WriteSyncerzapcore.LevelEnabler の3つの引数を必要とします

それぞれの引数の概要は以下のとおりです。

引数 概要
zapcore.Encoder ログフォーマット形式
zapcore.WriteSyncer 出力先
zapcore.LevelEnabler ログレベル

ようは、ログフォーマットと出力先の異なる複数の zapcore.NewCore() を持つ zapcore.Logger を作れればいいのですが、zapのソースコードを読んでいたらありました

というわけで具体的なコードです。

package logger

import (
    "log"
    "os"

    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
)

// NewLogger returns logger
func NewLogger() *zap.Logger {
    encoderConfig := zapcore.EncoderConfig{
        TimeKey:        "time",
        LevelKey:       "level",
        NameKey:        "name",
        CallerKey:      "caller",
        MessageKey:     "msg",
        StacktraceKey:  "stacktrace",
        EncodeLevel:    zapcore.LowercaseLevelEncoder,
        EncodeTime:     zapcore.ISO8601TimeEncoder,
        EncodeDuration: zapcore.StringDurationEncoder,
        EncodeCaller:   zapcore.ShortCallerEncoder,
    }

    file, _ := os.Create("app.log")

    consoleCore := zapcore.NewCore(
        zapcore.NewConsoleEncoder(encoderConfig), # コンソールで見やすい形式
        zapcore.AddSync(os.Stdout), # io.Writerをzapcore.WriteSyncerに変換
        zapcore.DebugLevel,
    )

    logCore := zapcore.NewCore(
        zapcore.NewJSONEncoder(encoderConfig), # 構造化ログ(JSON)
        zapcore.AddSync(file),
        zapcore.InfoLevel,
    )

    logger := zap.New(zapcore.NewTee(
        consoleCore,
        logCore,
    ))

    return logger
}

zapcore.NewTee() を使って zapcore.Core をまとめているのがポイントです。

というわけで

zapでやりたかったログ出力の形を実現できました。

構造化ログのフォーマットもltsvのエンコーダもあることを確認していますので、良さそうです。