Zabbixトラブルシューティング -Zabbix Serverログの見方-

みなさん、Zabbixを問題なく正常につかえてますか？
おかしな状態で動いてないですか？検知しそびれたり、重複検知したり変な挙動してませんか？

ということで、
Zabbix Advent Calendar 10日目は、Zabbixのトラブルシューティングについて少しご紹介します。トラブルシューティングの方法といっても非常に多くのポイントがあります。
今回は特にZabbix Server,Zabbix Agentのログにターゲットを絞ってご紹介します。

ログの出力設定

Zabbix Server,Zabbix Agent共にそれぞれの設定ファイル(zabbix_server.conf,zabbix_agentd.conf)にログの出力の設定を行います。

zabbix_server.conf,zabbix_agentd.confともに関連する設定は以下の3つぐらいです。

• LogFile
  • ログの出力先のファイル名を指定します。
• LogFileSize
  • 出力するログファイルのサイズの上限値をMB単位で指定します。(デフォルトは1MB)
• DebugLevel
  • ログに出力する内容のレベルを指定します。(デフォルトは3)
  • ※次の章で詳細は解説

ログレベルの解説

ログ分析するにあたってまず重要なのが、DebugLevelで指定できるログレベルの設定です。
ここを低レベルにしてしまうとそもそも情報として少なすぎて思い通りの分析ができません。

Zabbixのログレベル(DebugLevel)としては現状の最新バージョン(Zabbix2.4.7)では0-4まで指定可能です。
それぞれの意味はこちらにも書かれている通り以下となっています。

• 0: デバッグしない
  • 起動や停止時のログ等インフォメーションレベルの最低限しか出力されない。
• 1: 0に加えて致命的な情報
  • Zabbixの設定ファイルの記載内容がおかしいとか、Zabbix内部でメモリ割当ができないといったZabbixの稼働にあたって致命的な状態になった時に出力されます。
• 2: 1に加えてエラー情報
  • 監視設定がおかしくて監視ができない時など監視処理実行においてエラー状態になった時に出力されます。
• 3: 2に加えて警告情報
  • 上記の監視ができなくなったエラーがどういう理由からだったのかを示すための内部処理時の失敗情報等が出力されます。
• 4: 3に加えてデバッグ情報
  • さらに、詳細な分析のためにどの関数の処理がどのように行われたかなど内部処理の経過がわかるようなデバッグ情報が出力されます。

出力される内容の詳細についてはそれぞれソースコード内での以下のキーワードで検索してみて下さい。
Zabbixではログ出力用に内部関数zabbix_logというものが定義されています。その関数にレベルを渡してどのDebugLevelの指定時に出力するログなのかが決められています。

• 0: LOG_LEVEL_INFORMATION
• 1: 上記に加えてLOG_LEVEL_CRIT
• 2: 上記に加えてLOG_LEVEL_ERR
• 3: 上記に加えてLOG_LEVEL_WARNING
• 4: 上記に加えてLOG_LEVEL_DEBUG

4に設定した場合には各処理関数に入る度に様々なログが出力されることになるためログ出力量には注意してください。

ちなみに、DebugLevel 5というのも実は存在します。
設定ファイル上は0-4までしか設定できないのですが、Zabbix2.4系では後述するランタイムコントロールを使うことで5というレベルまで上昇させることが可能となっています。
DegugLevelを5にすることで、VMware監視やWebシナリオ監視等のより細かいトレースログを出力することが可能となります。
出力箇所はzabbix_logにLOG_LEVEL_TRACEを引き渡している箇所となります。
例えば、Webシナリオ監視の場合、各URLにアクセスして情報を取得した際のページ内に含まれているデータ情報等をログに出力します。
そのため5に設定すると非常に多くのデータが出力されることになるのでお気をつけください。

なお、Zabbix3.0ではランタイムコントロールによる指定だけでなく、zabbix_server.confやzabbix_agentd.conのDebugLevel設定でも5を指定できるようになります。

ログの見方

次にログの見方について解説します。
例えばDebugLevel=3(デフォルト)と設定した場合、以下のようなログが出力されます。

11590:20151206:083707.155 executing housekeeper
11590:20151206:083712.498 housekeeper [deleted 135 hist/trends, 0 items, 0 events, 0 sessions, 0 alarms, 0 audit items in 5.061329 sec, idle 1 hour(s)]

上記はハウスキーピング処理が実行された時のログです。
各行、実際の処理内容のログの前には以下の決まったフォーマットが付きます。

処理プロセスのID:年月日:時間

この例の場合だとプロセスID「11590」のZabbixServer内部プロセスが2015/12/6 8:37:07.155にハウスキーピング処理を開始。
その約5秒後に処理が完了して135件のヒストリ・トレンドデータが削除されたといった内容になります。
Zabbixのログの特徴的なところは、各ログにどのプロセスが処理したかを示すプロセスIDが付与されている点です。
Zabbixは内部で様々なプロセスが協調して動作しています。そのため、どのプロセスでどういった処理が実施されていてどこでおかしくなったのかを分析する必要があります。
それぞれのプロセスの処理を順序立てて追っていくことで原因の究明につながるので、このプロセスIDが同一のもののみをピックアップして処理を追いかけてみるというのが重要だったりします。
DebugLevelを4以上に設定すると、各プロセスがどの関数の中に入った、処理が終わって出たというのがすべて出力されるため、エラーを起こしている箇所がどの関数の中なのかを特定することが容易にできるようになります。
(もちろん、出力される量は多いので分析するには時間がかかりますが・・)

ログ解析の実例

もう一つログ解析の実例をご紹介しておきます。ログ監視処理時のデバッグログです。
例えば、以下のようなアイテムを登録したとします。

• タイプ: Zabbixエージェント(アクティブ)
• アイテムキー: log["/tmp/sample.log",error]
• 更新間隔: 1秒

errorという文字列が/tmp/sample.logに出力された時にZabbix Serverに監視結果として登録されるという設定です。
この設定を入れて1秒間隔で処理している時のAgentのログ(DebugLevel=4)です。

この/tmp/sample.logに以下のようなログが出力された時のAgentとServerのログを見てみましょう。

/tmp/sample.log

Tue Dec  8 20:46:34 JST 2015: error: this is error test

zabbix_agentd.log

 1行目: 14779:20151208:204634.511 process_logrt() old file list:
 2行目: 14779:20151208:204634.512    nr:0 filename:'/tmp/sample.log' mtime:1449575146 size:112 processed_size:112 seq:1 incomplete:0 dev:51713 ino_hi:0 ino_lo:19491 md5size:112 md5buf:bee3556ab0a5d2c699218f4c2221d9d5
 3行目: 14779:20151208:204634.512 process_logrt() new file list: (mtime:0 lastlogsize:112 start_idx:0)
 4行目: 14779:20151208:204634.512    nr:0 filename:'/tmp/sample.log' mtime:1449575194 size:168 processed_size:112 seq:0 incomplete:0 dev:51713 ino_hi:0 ino_lo:19491 md5size:168 md5buf:0292f9a8e86c6fe6a696fda684fe2cc3
 5行目: 14779:20151208:204634.512 In process_log() filename:'/tmp/sample.log' lastlogsize:112 mtime: 0
 6行目: 14779:20151208:204634.512 In process_value() key:'localhost:log[/tmp/sample.log,error,,,,]' value:'Tue Dec  8 20:46:34 JST 2015: error: this is error test'
 7行目: 14779:20151208:204634.512 In send_buffer() host:'127.0.0.1' port:10051 values:0/100
 8行目: 14779:20151208:204634.512 End of send_buffer():SUCCEED
 9行目: 14779:20151208:204634.512 buffer: new element 0
10行目: 14779:20151208:204634.512 End of process_value():SUCCEED
11行目: 14779:20151208:204634.512 End of process_log() filename:'/tmp/sample.log' lastlogsize:168 mtime: 0 ret:SUCCEED
12行目: 14779:20151208:204634.512 End of process_logrt():SUCCEED error_count:0

※Zabbix2.2.9の場合の例です

Agent側では1秒に1回の処理のタイミングで上記の1行目～4行目辺りで前回のチェックしたログファイルリストの情報と今回チェックする対象のログファイルのリスト情報を収集しています。
この時に得られたファイルの情報(mtime(更新時間)やsize(ログファイルサイズ)、i-node番号、ファイルの先頭512bytesのハッシュ値)をもとにファイルに追記が発生したかどうかをチェックします。
ここではmtime、lastlogsize(112bytes→168bytes)が更新されているので監視すべき対象として評価されていることがわかります。
6行目以降で実際にログファイルの中のerror文字列を含む行を検知したために情報をZabbix Serverに送付しているという感じです。
これで一連の流れが見て取れます。

zabbix_server.log

 14915:20151208:204635.513 trapper got '{
        "request":"agent data",
        "data":[
                {
                        "host":"localhost",
                        "key":"log[\/tmp\/sample.log,error,,,,]",
                        "value":"Tue Dec  8 20:46:34 JST 2015: error: this is error test",
                        "lastlogsize":168,
                        "clock":1449575194,
                        "ns":512476928}],
        "clock":1449575195,
        "ns":513006391}'

※Zabbix2.2.9の場合の例です
これに対して、Zabbix Server側では該当時間の辺りにAgent側から受け取った実際のログ監視結果の中身のデータが出力されます。

このような感じでそれぞれのログファイルの中身を確認することで監視処理の状況を追いかけることが可能となっています。

【おまけ】Zabbix2.4から使えるランタイムコントロール機能による動的なログ設定変更

本文中にも少し触れましたが、便利なランタイムコントロール機能についてご紹介します。
ランタイムコントロール機能は、Zabbix ServerやZabbix Agentが起動中であっても処理設定の情報を変更できる機能です。
具体的に言うと、通常ログの出力レベル(DebugLevel)はzabbix_server.confやzabbix_agentd.confに設定し、起動時に読み込まれて再起動するまでは変更されません。しかし、このランタイムコントロールの機能を使えば再起動なく、設定変更することが可能となります。
現状可能な設定としては以下があります。

• 設定キャッシュの再読み込み実行
• ログレベルを上げる
• ログレベルを下げる

ログレベルの上げ下げは、特定のプロセスに対してのみ実行するといったことも可能なので、何かおかしくなっているところだけ変更するといったことができるので便利です。

使い方は簡単！
zabbix_serverやzabbix_agentdのバイナリに対して-Rオプションを使って実行するだけ。

例: Zabbix Serverのpollerプロセスのログレベルを1つ上げる

# /usr/sbin/zabbix_server -R log_level_increase=poller

例: Zabbix Serverの特定のプロセスIDのログレベルを上げる

先ほどのログ・ファイルの読み方でも紹介したとおり各処理がどのプロセスで実行されているかがわかります。それを調べた上で、そのプロセスIDの処理ログのみレベルを上げるということも可能です。

# /usr/sbin/zabbix_server -R log_level_increase=11590

使いドコロ

よくトラブルになることが多いのがログ監視(ログローテート時とか)です。
ログローテートは多くの場合、特定の時間に実施される(夜間とか)と思うので、その前後の時間帯だけDebugLevelをあげてログを詳細にとっておくとかすると何かあった時に役立つかもしれないですね。
ただ単にコマンド実行するだけでOKなので、cronとかに仕込んでおけばOKかと思います。

まとめ

Zabbixは性能を良くするため、内部では非常に多くの処理をメモリで管理していたりします。
そのため、現在の状況をDBに格納されている情報や設定情報だけから判断することが難しかったりします。何かトラブルが発生した際には、ログの情報を的確に出力し、処理の流れを確認した上で実際にどういった結果が起こっているのかを判断することが重要となります。
起こってしまってからログの出力内容を見直すというのでは手遅れだったりもするので、今回ご紹介したような内容をもとに、自分の環境ではどのレベルまで出力して対応すべきかを見なおしてみるのはいかがでしょうか？

次回、第11日目は2box2boさんです。
よろしくお願いします！！