2013年1月6日日曜日

ログローテート

今回はMySQLで出力されるログのローテート設定を行いたいと思います。

MySQLのログには、エラーログ、一般クエリログ、スローログがあります。
エラーログは、MySQLの起動時などにエラーが発生した場合に記述されるログ。
一般クエリログは、MySQLが実行した全てのSQLのログ。
スローログは、実行されたSQLが指定された実行時間を超えた場合や、
インデックスなどが使われていないSQLが実行された場合などに記述されるログ。

と、なっています。

上記のログを設定していない場合にはmy.cnfで設定行い再起動しておく。(再起動すると各ログファイルが作成される)
ログローテーションの設定でログのファイル名の拡張子を利用して、
まとめて設定するので拡張子は.logで統一しておく。
#エラーログ
log-error = /var/lib/mysql/mysql-error.log
#一般クエリログ
general-log = ON
general-log-file = /var/lib/mysql/mysql-general.log
#スローログ
slow-query-log = ON
slow-query-log-file = /var/lib/mysql/mysql-slow.log
#SQL実行時間が指定された秒数を超えた場合にスローログに書き込む時間
long_query_time = 3
#インデックスが使われていないSQLをスローログに書き込む
log-queries-not-using-indexes
ローテーションを行いたいログファイルの確認
# ls -alt /var/lib/mysql/
合計 2865976
-rw-rw----  1 mysql mysql    5242880 12月 26 14:09 2012 ib_logfile0
-rw-rw----  1 mysql mysql    5242880 12月 26 14:09 2012 ib_logfile1
-rw-rw----  1 mysql mysql  211812352 12月 26 14:09 2012 ibdata1
-rw-rw----  1 mysql mysql       4082 12月 26 14:08 2012 mysql-bin.000018
drwx------  2 mysql mysql       4096 12月 26 14:08 2012 test
drwxr-xr-x  8 mysql mysql       4096 12月 25 20:25 2012 .
-rw-rw----  1 mysql mysql  559863407 12月 25 20:25 2012 mysql-bin.000017
-rw-rw----  1 mysql mysql        152 12月 25 20:25 2012 mysql-bin.index
-rw-rw----  1 mysql mysql 1073873533 12月 25 20:02 2012 mysql-bin.000016
-rw-rw----  1 mysql mysql 1074629396 12月 25 19:53 2012 mysql-bin.000015
drwx------  2 mysql mysql       4096 12月 25 19:43 2012 mysql
-rw-rw----  1 mysql mysql      24528 12月 25 19:32 2012 mysql-error.log
srwxrwxrwx  1 mysql mysql          0 12月 25 19:32 2012 mysql.sock
-rw-rw----  1 mysql mysql    1037542 12月 25 19:32 2012 mysql-bin.000014
-rw-rw----  1 mysql mysql      27335 12月 25 19:32 2012 mysql-bin.000013
drwx------  2 mysql mysql       4096 12月 25 19:32 2012 performance_schema
-rw-rw----  1 mysql mysql        508 12月 25 19:31 2012 mysql-bin.000012
-rw-rw----  1 mysql mysql        126 12月 25 19:15 2012 mysql-bin.000011
drwxr-xr-x 17 root  root        4096  9月 28 02:12 2012 ..
今回は、mysql-error.logをローテーションさせたいと思います。
#flush-logsを実行するためのmysqladminのパスの確認
# which mysqladmin
/usr/bin/mysqladmin
※rootにパスワードを設定している場合だと、
mysqladminを利用する際にパスワードを求められてしまうため、
/etc/my.cnfのmysqladminセクションにrootのパスワードを書く必要がある。

一部抜粋
http://colopl.co.jp/tech/blog/2012/06/1850/
MySQL の root パスワードを設定している場合、mysqladmin でもパスワードを引数に渡さなければ実行できません。
しかし、logrotate の設定ファイルに直接パスワードを書くのは気持ち悪いので、
ここでは別ファイルに実行ユーザ名とパスワードを記述しています。
サーバ標準の my.cnf にパスワードを記述してもよいのですが、コマンドラインからの実行時にもこのユーザ名とパスワードが使われてしまうのは危険ですので、
--defaults-extra-file オプションで別のファイルを併せて読み込むようにしています。
# /usr/local/etc/my.cnf
[mysqladmin]
user=root
password=hogefuga

デフォルトの/var/log/mysqld.logは、mysqld起動時のログになっていて、
my.cnfにlog-errorを設定することで出力先を変更できる
デフォルトの/etc/logrotate.d/mysqldの中身。
#ログファイルの場所の指定
#拡張子がlogのファイルを対象にする
/var/lib/mysql/*.log {
 #create 640 mysql mysql
 #ログファイルが空ならローテーションしない
 notifempty
 #ログを毎日ローテーションする
 daily
 #ローテーションする回数を指定
 rotate 3
 #ログファイルが存在しなくてもエラーを出さずに処理を続行
 missingok
 #ローテーションしたログをgzipで圧縮
 compress
 #postrotateとendscriptの間に記述されたコマンドをログローテーション後に実行
 postrotate
  # just if mysqld is really running
  #/usr/bin/mysqladminが実行可能ならば真
  if test -x /usr/bin/mysqladmin && \
   /usr/bin/mysqladmin ping &>/dev/null
  then
   #flush-logsを実行する
   /usr/bin/mysqladmin flush-logs
  fi
 endscript
}
デフォルトのものを参考に次のように変更します。
vi /etc/logrotate.d/mysqld
#ファイル名にlogが付くファイルを対象にする
/var/lib/mysql/*.log {
 #create 640 mysql mysql
 #ログファイルが空ならローテーションしない
 notifempty
 #ログを毎日ローテーションする
 daily
 #ローテーションする回数を指定
 rotate 3
 #ログファイルが存在しなくてもエラーを出さずに処理を続行
 missingok
 #ローテーションしたログをgzipで圧縮
 compress
 #末尾を日付にする
 dateext
 #末尾を日付にする際のフォーマット(Ymdしか使えない?)
 dateformat -%Y%m%d
 #ローテーションしたファイルの出力先
 olddir /tmp
 #複数のファイルをローテートの対象にすると、そのままでは、prerotate/postrotate共に、
 #ローテートが行われたファイルの数だけ実行されてしまうので1度だけ実行するように設定。
 sharedscripts
 #postrotateとendscriptの間に記述されたコマンドをログローテーション後に実行
 postrotate
  # just if mysqld is really running
  #/usr/bin/mysqladminが実行可能ならば真
  if test -x /usr/bin/mysqladmin && \
  /usr/bin/mysqladmin ping &>/dev/null
  then
  #flush-logsを実行する
  /usr/bin/mysqladmin flush-logs
  fi
 endscript
}
logrotateのオプション
・「-d」オプションが、テストで実行してみる(実際にはローテーションされない)オプションになります。
・「-v」オプションをつけてローテーションの様子を確認してみればよいです。
・-f オプションで強制的に実行する

ログローテートのテスト
# logrotate -dv /etc/logrotate.d/mysqld
reading config file /etc/logrotate.d/mysqld
reading config info for /var/lib/mysql/*.log

Handling 1 logs

rotating pattern: /var/lib/mysql/*.log  after 1 days (3 rotations)
empty log files are not rotated, old logs are removed
considering log /var/lib/mysql/mysql-error.log
  log does not need rotating
not running postrotate script, since no logs were rotated
ログローテートの実行(-vオプションをつけて実行時のログを出力する)
# logrotate -v /etc/logrotate.d/mysqld
reading config file /etc/logrotate.d/mysqld
reading config info for /var/lib/mysql/v2815.vir.kagoya.net.err

Handling 1 logs

rotating pattern: /var/lib/mysql/*.log  after 1 days (3 rotations)
empty log files are not rotated, old logs are removed
considering log /var/lib/mysql/*.log
  log does not need rotating
not running postrotate script, since no logs were rotated
あれ、うまくいっていない・・・?
considering log /var/lib/mysql/*.log
  log does not need rotating
ログローテートが実行されたか確認するには次のファイルの中身を見れば言いそうで、
実行された場合には、実行された日付が入るそうです。
cat /var/lib/logrotate.status
#今日の日付が書かれていた。
#ログの指定の際に正規表現などで指定していた場合には、その条件にマッチした分だけ行が追加されている
"/var/lib/mysql/mysql-error.log" 2013-1-4
"/var/lib/mysql/db02-slow.log" 2013-1-4
今日の日付があるということは実行されたっぽいけど、
ログファイルの数が、rotateの指定数より少ないとログローテートは実行されないけど、
/var/lib/logrotate.statusには今日の日付が書き込まれてしまう?

この場合には、ここに書かれている日付を
cat /var/lib/logrotate.status
#今日の日付が書かれていた。
#ログの指定の際に正規表現などで指定していた場合には、その条件にマッチした分だけ行が追加されている
"/var/lib/mysql/mysql-error.log" 2013-1-1
"/var/lib/mysql/db02-slow.log" 2013-1-1
のように過去の日付にしてあげてから実行すれば(・∀・)イイ!!
# logrotate -v /etc/logrotate.d/mysqld
reading config file /etc/logrotate.d/mysqld
reading config info for /var/lib/mysql/*.log

Handling 1 logs

rotating pattern: /var/lib/mysql/*.log  after 1 days (3 rotations)
empty log files are not rotated, old logs are removed
considering log /var/lib/mysql/db02-slow.log
  log does not need rotating
considering log /var/lib/mysql/mysql-error.log
  log needs rotating
running postrotate script
rotating log /var/lib/mysql/db02-slow.log, log->rotateCount is 3
dateext suffix '-20130104'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/lib/mysql/db02-slow.log.3.gz to /var/lib/mysql/db02-slow.log.4.gz (rotatecount 3, logstart 1, i 3),
old log /var/lib/mysql/db02-slow.log.3.gz does not exist
renaming /var/lib/mysql/db02-slow.log.2.gz to /var/lib/mysql/db02-slow.log.3.gz (rotatecount 3, logstart 1, i 2),
old log /var/lib/mysql/db02-slow.log.2.gz does not exist
renaming /var/lib/mysql/db02-slow.log.1.gz to /var/lib/mysql/db02-slow.log.2.gz (rotatecount 3, logstart 1, i 1),
old log /var/lib/mysql/db02-slow.log.1.gz does not exist
renaming /var/lib/mysql/db02-slow.log.0.gz to /var/lib/mysql/db02-slow.log.1.gz (rotatecount 3, logstart 1, i 0),
old log /var/lib/mysql/db02-slow.log.0.gz does not exist
log /var/lib/mysql/db02-slow.log.4.gz doesn't exist -- won't try to dispose of it
renaming /var/lib/mysql/db02-slow.log to /var/lib/mysql/db02-slow.log.1
running postrotate script
compressing log with: /bin/gzip
running postrotate script
rotating log /var/lib/mysql/mysql-error.log, log->rotateCount is 3
dateext suffix '-20130104'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/lib/mysql/mysql-error.log.3.gz to /var/lib/mysql/mysql-error.log.4.gz (rotatecount 3, logstart 1, i 3),
old log /var/lib/mysql/mysql-error.log.3.gz does not exist
renaming /var/lib/mysql/mysql-error.log.2.gz to /var/lib/mysql/mysql-error.log.3.gz (rotatecount 3, logstart 1, i 2),
old log /var/lib/mysql/mysql-error.log.2.gz does not exist
renaming /var/lib/mysql/mysql-error.log.1.gz to /var/lib/mysql/mysql-error.log.2.gz (rotatecount 3, logstart 1, i 1),
old log /var/lib/mysql/mysql-error.log.1.gz does not exist
renaming /var/lib/mysql/mysql-error.log.0.gz to /var/lib/mysql/mysql-error.log.1.gz (rotatecount 3, logstart 1, i 0),
old log /var/lib/mysql/mysql-error.log.0.gz does not exist
log /var/lib/mysql/mysql-error.log.4.gz doesn't exist -- won't try to dispose of it
renaming /var/lib/mysql/mysql-error.log to /var/lib/mysql/mysql-error.log.1
running postrotate script
compressing log with: /bin/gzip

#ローテートされているか確認する
# ls -alt /var/lib/mysql/*.log*
-rw-rw---- 1 mysql mysql 181  1月  4 14:14 2013 /var/lib/mysql/db02-slow.log.1.gz
-rw-rw---- 1 mysql mysql   0  1月  4 14:08 2013 /var/lib/mysql/mysql-error.log
-rw-rw---- 1 mysql root  868  1月  4 14:08 2013 /var/lib/mysql/mysql-error.log.1.gz
ログローテーションの設定は以上です(`・ω・´)ゞビシッ!!

次回は、ログローテーションを行う際に、
スローログを解析した結果をメールに送るように設定したいと思います(ΦωΦ)フフフ…

/etc/logrotate.d/にログローテートのファイルを作成する際の注意として、
次の点があるそうです。
一部抜粋
http://isolinear.info/blog/archives/cat16/cat10/
2005年2月14日
logrotate が動かなくなる
カテゴリー: [自宅サーバ]
どうも,ログファイルが大きくなると思っていたら,しばらく前から,logrotate が動いていなかったようです
# /usr/sbin/logrotate /etc/logrotate.conf
として,直接実行してみたら,こんなエラーが出ました.
error: syslog-ng:7 duplicate log entry for /var/log/messages
エントリーが重複しているというのですが,そのファイルには重複が見あたりません.Google で調べたりしているうちに,バックアップしてある他のファイルの内容と重複していることがあり得ることがわかりました.

ひょっとして,と思い,/etc/logrotate.d/ 以下で,ls -la としてみると,やはり ._cfg0000_syslog-ng というファイルがありました.Gentoo Linux のパッケージ管理システムの emerge が,パッケージをアップデートする際に既存の設定ファイルを上書きしないように,ファイル名を変えてインストールした設定ファイルです.

この中に,/var/log/messages のエントリがあったため,エラーが出ていたわけです.この前syslog-ngを更新したときにできたんでしょう.._cfg0000_syslog-ng を削除したら,直りました.
しかし,このファイルが出来ている事に気づかないと,いつの間にか悪さをしている可能性もあるということですよね.ドットファイルも含むとは思わなかったので,ちょっとはまりました.


スローログをローテートするついでに、管理者にメールを送信したいと思います!(ΦωΦ)フフフ…
上記のローテートの設定に次の行を追加します。
まず、直接コマンドでメールを送信してみる。
(メール送信用のsendmail,postfixなどのが入ってるのが前提になります。)
$ which postfix
/usr/sbin/postfix

#スローログの解析結果を指定のアドレスへ送信する
/usr/bin/mysqldumpslow -s t -t 100 /data/mysql-log/mysql-slow.log 2>/dev/null | mail -s "Mysql Slowlog Report" 送信先メールアドレス
上記のコマンドで正常にメールが受信できた場合には、
次に、このコマンドをログローテートのprerotateに組み込みます。
#ファイル名にlogが付くファイルを対象にする
/var/lib/mysql/*.log {
        #create 640 mysql mysql
        #ログファイルが空でもローテーションする
        ifempty
        #ログファイルが空ならローテーションしない
#       notifempty
        #ログを毎日ローテーションする
        daily
        #ローテーションする回数を指定
        rotate 3
        #ログファイルが存在しなくてもエラーを出さずに処理を続行
        missingok
        #ログローテーション先のディレクトリの指定
        olddir /tmp
        #
        dateext
        dateformat -%Y%m%d
        #複数のファイルをローテートの対象にすると、そのままでは、prerotate/postrotate共に、
        #ローテートが行われたファイルの数だけ実行されてしまうので1度だけ実行するように設定。
        sharedscripts
        #ローテーションしたログをgzipで圧縮
        compress
        #ローテートを実行する前にスローログを解析してその結果を管理者へメールを送る
        prerotate
                /usr/bin/mysqldumpslow -s t -t 100 /var/lib/mysql/mysql-slow.log 2>/dev/null | mail -s "Mysql Slowlog Report" メールアドレス
        endscript
        #postrotateとendscriptの間に記述されたコマンドをログローテーション後に実行
        postrotate
                # just if mysqld is really running
                #/usr/bin/mysqladminが実行可能ならば真
                if test -x /usr/bin/mysqladmin && \
                        /usr/bin/mysqladmin ping &>/dev/null
                then
                        #flush-logsを実行する
                        /usr/bin/mysqladmin flush-logs
                fi
        endscript
}
これで、ログローテートされるタイミングで、
スローログが解析され、その結果が指定のアドレスへ送信されるようになります(・∀・)イイ!!
スローログの解析を行う場合には、
実際にアプリケーションから参照されているDBサーバーじゃない方が
無駄な負荷がかからないのでそちらの方が良いかもです!

mysqldumpslowについてはこちらを参照してください(`・ω・´)ゞビシッ!!

■mysqldumpslowの結果をメール送信している時に起きた問題

コマンドから送信されたメールをgmailで確認してみると、
なぜか添付ファイルにnonameというファイルが添付されていて、
本文は空でした( ゚д゚)ポカーン

ただ、nonameというファイルにtxtという拡張子をつけて中身を見てみると、
解析結果が普通に書かれていました・・・orz

メール送信に失敗しているのかな?もしくは記述が正しくないとか・・・:(;゙゚'ω゚'):
で、コマンドの内容を色々を変えていたら
mysqldumpslowのコマンドのオプションで取得する件数を指定している場合には、
正常に本文に出力され、指定無しだとnonameという添付ファイルが作られて送られてくる事に気づきましたド━━━━m9(゚∀゚)━━━━ン!!

とりあえず、取得件数を指定して使うようにしたので、
問題は回避できましたが、根本的な原因は何だったのだろうか・・・?
#こっちはnonameという添付ファイルが送られてきてしまう・・・ガ━━(;゚Д゚)━━ン!!
/usr/bin/mysqldumpslow -s t /var/lib/mysql/mysql-slow.log 2>/dev/null | mail -s "Mysql Slowlog Report" メールアドレス

#こっちは問題なし
/usr/bin/mysqldumpslow -s t -t 100 /var/lib/mysql/mysql-slow.log 2>/dev/null | mail -s "Mysql Slowlog Report" メールアドレス

参考URL

0 件のコメント:

コメントを投稿