[さくらのVPS]サーバー監視がとても捗るlogwatchを入れてみた

2022/6/17 記事

前回はVPSに移行したこのブログがhttpdごと落ちまくって大変だった話でしたが、今回は問題解決の過程で入れてみたlogwatchのお話です。

※サーバはさくらのVPS 512で、OSはCentOS5.6です。

logwatchとは、サーバのログを解析しやすい形に変えて通知してくれる便利な監視ツールです。デフォルトの設定なら、/var/logにあるログをひと通りチェックして、サービスごとに、そして見るべきチェック項目ごとに、見やすいかたち整理してメールで通知してくれる、とても気の利いたサーバ監視ツールです。

チェックしてくれるサービスは環境によって異なると思いますが、僕の環境だとデフォルトで下記のサービスをチェックしてくれています。

たとえばApacheのaccess_logひとつとっても、手作業でチェックするのは（僕にとって）途方もない作業ですが、logwatchが届けてくれるログメールを見れば、どのIPアドレスからおかしなアクセスがあるとか、エラーレスポンスコードごとに、どのパスに対してのアクセスで何回エラーが出ているとか、ひと目でわかります。

僕みたいな素人でもこうした情報を元にすれば、不正なアクセスを防いだり、サーバにどんな問題があるのか調べるのも容易になるというものです。

それではまず、どのようなログがチェックできるのか見ていただいたあと、logwatchのインストール、設定方法について説明します。

Logwatchが届けてくれるログ解析メール

logwatchをインストールすると何も設定しなくても、サーバで動いているサービスのログを解析してくれます。
それでは僕の環境を参考に、どのような解析結果が見れるのかサービスごとに紹介していきます。*1

Dovecot（POP/IMAPサーバー）

Dovecot(ダヴコット)とは、Timo Sirainenが開発・公開をしている、UNIXライクなOS上で動作する、POP3/IMAPに対応したメール配送エージェントである。
via : Dovecot – Wikipedia

だそうです。僕の頭の中ではPOPサーバ、つまりメール受信サーバぐらいの認識ですが、とりあえずそれで問題なさそう。
そして、このDovecotのログは次のような形で出力してくれます。

 --------------------- Dovecot Begin ------------------------
 Dovecot disconnects:
   Logged out: 189 Time(s)
   no reason: 1 Time(s)
 ---------------------- Dovecot End -------------------------

Dovecotのログはデフォルトで/var/log/sendmailに書きこまれます。
sendmailログにはsendmail(SMTPサーバ）のログなんかも一緒に書きこまれているので、そのまま閲覧するとゴチャゴチャしています。

grepでDovecotだけ抽出しても、状態ごとにチェックするにはひと工夫しなくてはなりません。

でもlogwatchならば、Logged out（正常終了）が189回、理由なく受信に失敗した？が1回とひと目で分かります。

上記のサンプルにはありませんが、認証に失敗したりするとそうしたログもこちらに出力されると思います。

参考：/var/log/maeda.log: DovecotのPOP3ログの見方

ftpd（FTPサーバ）

FTPサーバです。

 --------------------- ftpd-xferlog Begin ------------------------
 TOTAL KB OUT: 3KB (0MB)
 TOTAL KB IN: 468KB (0MB)
 ---------------------- ftpd-xferlog End -------------------------

上記のログは、多分FTPでListの取得しかしていないから微量のIN/OUTしか出力されていないのかな？

多分、FTPでUploadやDownloadすれば、どのIPアドレスから接続して、どのファイルをUp/Downして、トータルどのくらいの転送が行われたかが表示されると思います。

参考：vsftpdの設定例 – satospo

httpd（WEBサーバ）

皆さんお待ちかね、Webサーバのログです（Apache）。

 --------------------- httpd Begin ------------------------

 A total of 3 sites probed the server
   119.63.196.58
   69.171.224.251
   69.171.228.244

 A total of 3 possible successful probes were detected (the following URLs
 contain strings that match one or more of a listing of strings that
 indicate a possible exploit):

  #probeが成功しちゃったパスなど

 Requests with error response codes
   400 Bad Request
      HTTP/1.1: 1 Time(s)
   404 Not Found
      *: 1194 Time(s)
      /%0D/scripts/setup.php: 1 Time(s)
      //admin/index.php: 4 Time(s)
      //admin/phpmyadmin/index.php: 3 Time(s)
      //admin/pma/index.php: 4 Time(s)
      //db/index.php: 4 Time(s)
      //dbadmin/index.php: 4 Time(s)
      //myadmin/index.php: 3 Time(s)
      //mysql/index.php: 4 Time(s)
      //mysqladmin/index.php: 4 Time(s)
      //php-my-admin/index.php: 8 Time(s)
      //phpMyAdmin-2.2.3/index.php: 4 Time(s)
      //phpMyAdmin-2.2.6/index.php: 4 Time(s)
      //phpMyAdmin-2.5.1/index.php: 4 Time(s)
      //phpMyAdmin-2.5.4/index.php: 4 Time(s)
      //phpMyAdmin-2.5.5-pl1/index.php: 4 Time(s)
      //phpMyAdmin-2.5.5-rc1/index.php: 4 Time(s)
      //phpMyAdmin-2.5.5-rc2/index.php: 4 Time(s)
      //phpMyAdmin-2.5.5/index.php: 4 Time(s)
      //phpMyAdmin-2.5.6-rc1/index.php: 4 Time(s)
      //phpMyAdmin-2.5.6-rc2/index.php: 4 Time(s)
      //phpMyAdmin-2.5.6/index.php: 4 Time(s)
      //phpMyAdmin-2.5.7-pl1/index.php: 4 Time(s)
      //phpMyAdmin-2.5.7/index.php: 4 Time(s)
      //phpMyAdmin-2/index.php: 4 Time(s)
      -もっと膨大にログがありますが割愛-
   500 Internal Server Error
      *: 86 Time(s)
      /: 30 Time(s)
      -割愛-

 ---------------------- httpd End -------------------------

まず最初の「A total of 3 sites probed the server」ですが、ここで言うprobedとはポートスキャンやアクセス可能なファイルを探査する“良くない行為“のことを言うようです。つまり、それ以下に記載された３つのIP（sites）から、プローブ（良くない探査行為）を受けたってことのようですね。

これを膨大なアクセスログから手作業や目視で見つけるのは大変なことですが、logwatchなら簡単に見つけてIPを提示してくれるんですね。頼もしい！

IPアドレスさえわかれば、whoisコマンドやドメイン/IPアドレス【whois情報検索】などで素性をしらべて、簡単にアクセスを拒否することができます。

次に「A total of 3 possible successful probes were detected….」ですがこれは、それ以下に記載されたパス（書けないので隠してます）に、プローブが成功したみたいよ。って事のようです。

なので、一般にアクセスされてまずいファイルであればアクセス制限を掛けたり、セキュアな場所に移すなどの処置がとれそうです。

最後に「Requests with error response codes」ですが、エラーレスポンスコードごとに、どのパスに何回アクセスがあってエラーが返されたかが一覧になっています。

膨大な量なのでログの大部分を割愛しましたが、見てもらうと分かる通りAdminっぽいパスにアクセスしてきたり、phpMyAdminのバージョンごとに異なるパスに総当たりでアクセスされているのがわかります。こいつ、悪いやつですよ(-_-メ)

ただ、こうしたことをチェックできると、不正なアクセスからアクセス拒否や危ないファイルを隠したりする対応策を考えることができるわけですね。もちろんただのリンク切れって場合もありますけどσ(^_^;)

Kernel

カーネルに関するログです。僕はまだカーネルの概念をうまく理解できていないんですが、アンパンマンで言うところのアン？という説明がされた、こちらが参考になりそうです。

参考：カーネルとはどんな意味ですか？ – BIGLOBEなんでも相談室
用語：カーネルとは【kernel】 – 意味/解説/説明/定義 ： IT用語辞典

 --------------------- Kernel Begin ------------------------
 WARNING:  Kernel Errors Present
    [<ffffffff8005dde9>] error_exit+0x0/0x84 ...:  228 Time(s)
 ---------------------- Kernel End -------------------------

上記では見事にエラーが出ていますね。messageログを調べるとexitの前にその原因が記載されていました。

参考：サーバー管理について…。。。 現在さくらVPSにてSNSを運営しております。。 本日サ… – Yahoo!知恵袋

Feb  1 03:18:34 **** kernel: Mem-info:
Feb  1 03:18:34 **** kernel: Node 0 DMA per-cpu:
Feb  1 03:18:34 **** kernel: cpu 0 hot: high 0, batch 1 used:0
Feb  1 03:18:34 **** kernel: cpu 0 cold: high 0, batch 1 used:0
Feb  1 03:18:34 **** kernel: cpu 1 hot: high 0, batch 1 used:0
Feb  1 03:18:34 **** kernel: cpu 1 cold: high 0, batch 1 used:0
Feb  1 03:18:34 **** kernel: Node 0 DMA32 per-cpu:
Feb  1 03:18:34 **** kernel: cpu 0 hot: high 186, batch 31 used:30
Feb  1 03:18:34 **** kernel: cpu 0 cold: high 62, batch 15 used:54
Feb  1 03:18:34 **** kernel: cpu 1 hot: high 186, batch 31 used:45
Feb  1 03:18:34 **** kernel: cpu 1 cold: high 62, batch 15 used:58
Feb  1 03:18:34 **** kernel: Node 0 Normal per-cpu: empty
Feb  1 03:18:34 **** kernel: Node 0 HighMem per-cpu: empty
Feb  1 03:18:34 **** kernel: Free pages:        4792kB (0kB HighMem)
Feb  1 03:18:34 **** kernel: Active:60398 inactive:32787 dirty:0 writeback:0 unstable:0 free:1198 slab:5454 mapped-file:1088 mapped-anon:93728 pagetables:20265
Feb  1 03:18:34 **** kernel: Node 0 DMA free:2008kB min:52kB low:64kB high:76kB active:0kB inactive:20kB present:9760kB pages_scanned:14035 all_unreclaimable? yes
Feb  1 03:18:34 **** kernel: lowmem_reserve[]: 0 489 489 489
Feb  1 03:18:34 **** kernel: Node 0 DMA32 free:2784kB min:2800kB low:3500kB high:4200kB active:241796kB inactive:130924kB present:500952kB pages_scanned:2460487 all_unreclaimable? yes
Feb  1 03:18:34 **** kernel: lowmem_reserve[]: 0 0 0 0
Feb  1 03:18:34 **** kernel: Node 0 Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Feb  1 03:18:34 **** kernel: lowmem_reserve[]: 0 0 0 0
Feb  1 03:18:34 **** kernel: Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
Feb  1 03:18:34 **** kernel: lowmem_reserve[]: 0 0 0 0
Feb  1 03:18:34 **** kernel: Node 0 DMA: 0*4kB 1*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2008kB
Feb  1 03:18:34 **** kernel: Node 0 DMA32: 34*4kB 65*8kB 13*16kB 4*32kB 2*64kB 1*128kB 0*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2784kB
Feb  1 03:18:34 **** kernel: Node 0 Normal: empty
Feb  1 03:18:34 **** kernel: Node 0 HighMem: empty
Feb  1 03:18:34 **** kernel: 2692 pagecache pages
Feb  1 03:18:34 **** kernel: Swap cache: add 6941350, delete 6940769, find 378205/1337738, race 259+1235
Feb  1 03:18:34 **** kernel: Free swap  = 0kB
Feb  1 03:18:34 **** kernel: Total swap = 2048276kB
Feb  1 03:18:34 **** kernel: Free swap:            0kB
Feb  1 03:18:34 **** kernel: 131069 pages of RAM
Feb  1 03:18:34 **** kernel: 3621 reserved pages
Feb  1 03:18:34 **** kernel: 40311 pages shared
Feb  1 03:18:34 **** kernel: 586 pages swap cached
Feb  1 03:18:34 **** kernel: Out of memory: Killed process ****, UID ***, (httpd).
Feb  1 03:18:34 **** kernel: httpd invoked oom-killer: gfp_mask=0x201d*, order=0, oomkilladj=0
Feb  1 03:18:34 **** kernel:
Feb  1 03:18:34 **** kernel: Call Trace:
Feb  1 03:18:34 **** kernel:  [<ffffffff800c962a>] out_of_memory+0x8*/0x2f3
Feb  1 03:18:34 **** kernel:  [<ffffffff8000f625>] __alloc_pages+0x2*f/0x308
Feb  1 03:18:34 **** kernel:  [<ffffffff8001300a>] __do_page_cache_readahead+0x9*/0x179
Feb  1 03:18:34 **** kernel:  [<ffffffff80013945>] filemap_nopage+0x14*/0x360
Feb  1 03:18:34 **** kernel:  [<ffffffff80008964>] __handle_mm_fault+0x1f*/0x1039
Feb  1 03:18:34 **** kernel:  [<ffffffff8006720b>] do_page_fault+0x4c*/0x874
Feb  1 03:18:34 **** kernel:  [<ffffffff80062ff0>] thread_return+0x6*/0xfe
Feb  1 03:18:34 **** kernel:  [<ffffffff8000e2a5>] do_mmap_pgoff+0x61*/0x780
Feb  1 03:18:34 **** kernel:  [<ffffffff8009a47e>] recalc_sigpending+*xe/0x25
Feb  1 03:18:34 **** kernel:  [<ffffffff8005dde9>] error_exit+0x*/0x84

ほら、例の殺し屋がいますよ（笑）
メモリが無くってスワップも0kBになっちゃって、Out of memory:だからプロセスID:****、UID:***の(httpd)落としてやったぜぃ！みたいな。

なるほど、調べてみるとログがちゃーんとおかしくなった原因を教えてくれるんですね。
※どの情報を出したらまずいのか判断できないんですが↑は大丈夫ですよね？ｗヤバかったら教えてください、親切なお方さまへ。

pam_unix

pam_unixとは一般ユーザがsuコマンドでスパーユーザになったログのようです。

参考：＠IT：suコマンドでスーパーユーザーになったユーザーを調べるには

これはちょっとログを書きづらいんで代わりに説明します。

suコマンドで、誰が何回スーパーユーザになったかのログです。
また、パスワード入力をミスした場合にはその回数も記録されています。

sendmail（SMTPサーバ）

SMTPサーバ、メール送信サーバに関するログです。
でも書かれていることが全然わからない・・・（笑）

 --------------------- sendmail Begin ------------------------
 SEVERE ERRORS
 -------------

 System Error Messages:
    returntosender: cannot select queue for postmaster: 1 Time(s)
    returntosender: cannot select queue for root: 1 Time(s)

 Error "No space left on device" occurred 2 time(s)

 Total SEVERE ERRORS:  4

 SENDMAIL CONFIGURATION
 ----------------------

 Warning: Low space when writing to:
    /var/spool/clientmqueue
    /var/spool/mqueue

 Daemon started rejecting messages 5 times due to lack of space

 **Unmatched Entries**
   have been rejecting connections on daemon MTA for 07:33:33: 1 Time(s)
   have been rejecting connections on daemon MSA for 07:26:26: 1 Time(s)

 ---------------------- sendmail End -------------------------

調べたんですが、さっぱりわかりません。
開いていないエラーメッセージがpostmasterとrootに1通ずつある？違うか。わかりませんｗ
まあsendmailの生のログはもっとわけがわからないので、これでも十分整理された解析情報なんでしょうね。

参考：Sendmailのログの読み方を解説しているサイトを教えて下さい。 人力検索はてな

SSHD（SSHサーバ）

どのIP（ホスト）から、どのユーザで、何回ログインしたかが記載されます。

Sudo(secure-log)

Sudoで実行したコマンドのログのようです。

 --------------------- Sudo (secure-log) Begin ------------------------

 ------------------------------------------------------------------------------
 /bin/vi /etc/httpd/conf/httpd.conf
 /bin/vi /etc/php.ini
 /bin/vi /etc/my.cnf
 /bin/vi /etc/httpd/conf/httpd.conf
 /sbin/service httpd restart
 /bin/vi /etc/my.cnf
 /sbin/service mysqld restart
 /bin/vi /etc/my.cnf
 /sbin/service mysqld restart
 /sbin/service mysqld start
 /bin/vi /etc/my.cnf
 /sbin/service mysqld start
 /bin/vi /etc/my.cnf
 /sbin/service mysqld start
 /bin/vi /etc/my.cof
 /bin/vi /etc/my.cnf
 /sbin/service mysqld restart
 /bin/vi /etc/my.cnf
 /bin/vi /etc/httpd/conf/httpd.conf
 /sbin/service httpd restart
 /bin/vi /etc/httpd/conf/httpd.conf
 /sbin/service httpd restart
 /bin/vi /etc/httpd/conf/httpd.conf
 /bin/vi /etc/my.cnf
 /sbin/service mysqld restart
 /bin/vi /etc/my.cnf
 /bin/vi /etc/my.cnf
 /bin/vi /etc/my.cnf
 /sbin/service mysqld start
 /bin/cp /etc/my.cnf .my.cnf.20120201
 /bin/vi /etc/my.cnf
 /bin/vi /etc/my.cnf
 /usr/bin/du -k /
 /usr/bin/find /var -name access_log
 /bin/ls /var/log/httpd/
 /bin/vi /etc/httpd/conf/httpd.conf
 /usr/bin/tailf /var/log/httpd/access_log
 /usr/bin/tailf /var/log/httpd/access_log -n 20
 /usr/bin/tailf /var/log/httpd/access_log
 /bin/grep OOM /var/log/messages
 /bin/grep OOM /var/log/messages
 /bin/grep killer /var/log/message
 /bin/grep killer /var/log/messages
 /bin/vi /etc/httpd/conf/httpd.conf
 /bin/vi /etc/httpd/conf/httpd.conf
 /bin/grep killer /var/log/messages
 /bin/vi /etc/php.ini
 /bin/vi /etc/httpd/conf/httpd.conf

 ---------------------- Sudo (secure-log) End -------------------------

べ、別に見せても大丈夫ですよね？
それにしてもわけがわからないでしょう？（笑）

多分ちょうどhttpdが落とされる原因を調べたり、httpd.confの同時接続数をチューニングしている時のログだと思います。きっと見る人が見れば「何やってんの( ﾟдﾟ)」って感じなんだろうな。でも、恥を晒します(/ω?)

XNTPD(NTPサーバ・タイムサーバ)

時間を調節してくれるタイムサーバ*2 のログです。

 --------------------- XNTPD Begin ------------------------
 XNTPD Started: 6 Time(s)

 Time Reset 6 times (total: 8.800035 s  average: 1.466673 s)

 Total interfaces 6 (non-local: 2)

 Total synchronizations 17 (hosts: 2)
 ---------------------- XNTPD End -------------------------

NTPサーバの起動が6回（も！？rebootのタイミングで走るのかな？）
時間をリセットした回数6回。合計とか平均ってのは正確な時間との誤差のことなのかな？
最後の17回が同期回数？すみません、このへんは全然気にならないのでスルーしますｗ

ディスクスペース

さあ、最後です！
ディスク容量についてのログです。

 --------------------- Disk Space Begin ------------------------
 Filesystem            Size  Used Avail Use% Mounted on
 /dev/hda2              17G  3.0G   13G  19% /
 /dev/hda1              99M   18M   77M  19% /boot
 ---------------------- Disk Space End -------------------------

見たままです。説明はいりませんね？
logwatchをインストールしておくだけで、（デフォルトで）毎日このようなログをメールで送ってきてくれます。
忙しいサーバ管理者のあなたは、朝（じゃなくてもいいけど）サッとこのメールに目を通すだけ。何かあれば、これを頼りに調べれば、何も情報なく調べるのの何倍も効率よく問題解決にあたれます。

logwatchって素晴らしいでしょう！（ステマじゃないです）
さて、logwatchでどんなログがチェックできるのか見ていただいたところでインストール方法と、設定方法の説明をしましょう。

logwatchをインストール

それではlogwatchのインストール方法です。

$ sudo yum install logwatch

はい、インストールしゅーりょー。
めちゃめちゃ簡単でしょう？（笑）

動作確認は

$ sudo /usr/sbin/logwatch --print

–printオプションをつけると、先ほど見ていただいた解析ログをコンソールで見ることができます。

参考：さくらのVPS ログレポート(logwatch)と不正アクセス拒否(denyhosts)のインストール | webプログラマーのメモ

logwatchの設定

最後にlogwatchの設定方法です。

下記の参考URLがとても詳しいですが、必要な項目だけを抜粋しますね。
参考：＠IT：サーバのログ監視ツールを使いこなそう（3/3）

/etc/logwatch/conf/logwatch.conf

# Local configuration options go here (defaults are in /usr/share/logwatch/default.conf/logwatch.conf)
# ↓以下に設定を追加していく

#解析結果を送信するメールアドレス
MailTo=hoge@hoge.com

#解析結果をファイルに保存する場合はSave=保存するパス
Save=/home/hoge 	
#解析するログの期間を指定する場合はRange=mixed
Range=All|Today|Yesterday

他にもデフォルトでコンソール出力にしたり、解析結果の詳細度を設定できたりと、かゆいところに手が届く設定が可能です。

ちなみに僕はMailToのみで、他は何も設定していません。

最後に

ログのサンプルを掲載したら長くなってしまいましたね。
でも、僕のように「どうやったらサーバの監視ができるんだろう？」というレベルの人は、サーバに新しいツールを入れるだけでも不安だと思うんですよね。

それに、そのツールを使ってどんなことが出来るのかというのも、自分ではなかなか調べるのは難しいんじゃないでしょうか。

なので、（めちゃめちゃ長くなっちゃいましたが）まずどんな解析結果のログがチェックできるのか見ていただいて、それからインストール方法を説明しました。

さいわいlogwatchのインストールは超簡単ですし、設定もほとんど必要ありませんから、得られるメリットに比べてリスクが非常に少ないですよね。

VPSを使い始めたけどサーバ監視はしていないという方は、ぜひチャレンジしてみて欲しいですね。

僕もこのブログをVPSに移行したときには、突然動かなくなってしまってアタフタしたり、どうやって原因を調べていいのかわからなかったり、原因がわかっても修正方法がわからなかったりと、最初はわからないことばかりでしたが、たった1日2日で結構できることが増えました^^

そう考えると、どうしてもクリアしなければならないトラブルに見舞われたほうが、きっと早く上達できると思います。

というわけで、これからも玉砕覚悟で色々チャレンジしていこうと思います（笑）

  1. セキュリティ上まずそうなところは隠蔽したり値を変えたりします [↩]
  2. タイムサーバって呼び名ありませんでしたっけ？Windowsだと時刻サーバとかってなってますね [↩]
スポンサーリンク
336x280_1
336x280_1

シェアする

  • このエントリーをはてなブックマークに追加

フォローする

, suzuki

スポンサーリンク
336x280_1