Rails初心に還った人のメモ。f2p(ffp)からsyslogを出させてみる(修正有)
SyslogLogger
参考記事：Railsアプリケーションのログをsyslogに記録する方法 - Hello, world! - s21g
上の記事のまんまだと、f2p/log/(development|production).log に出てくるのと一緒（追記註：実は英語以外の情報は失われることがあるらしい）の詳細なログになっちゃうので、あえて infoのレベル以上のものだけ採取してみる。（ＯＳはCentOS5.2なので、BSD系などはsyslogの設定が異なるかも）
- sudo gem install SyslogLogger
- config/environments/(development|production).rbに以下を追加
# SyslogLogger require 'syslog_logger' RAILS_DEFAULT_LOGGER = SyslogLogger.new 'f2p'
- /etc/syslog.confに以下を追加。これだけだと全体のsyslogを受ける/var/log/messages なんかにも出てしまうが、そちらは f2p.none などという指定をすることもできる。また、外部のログサーバに飛ばしたい場合には、ログファイルではなくて、'@logservername' という指定もできる。その際には、受け手のログサーバのファイアウォールでudpの514番ポートが開かれていることと、syslogの起動オプションに'-r'が指定されてremoteサーバからの入力を受け入れられることを確認しておく。(以下、facilityの指定のところを参考リンクのページの形式にしました。）
# f2p server specific log !f2p *.info /var/log/f2p.log
(2009/2/21:追記 syslog-ngで、サーバ内部からのメッセージ源をs_localとして定義してある場合:CentOS(Redhat系)
#
# Local sources
#
source s_local {
unix-dgram("/dev/log");
file("/proc/kmsg" log_prefix("kernel:"));
};
(中略)
destination f2p_log { file("/var/log/f2p.log"); };
filter f_f2p { program("f2p.*") and level(info..emerg); };
log { source(s_lccal); filter(f_f2p); destination(f2p_log); };
追記終わり）
一度ログアウトして、またログインした時の出力はこんな感じ。Webrickのアクセスログと、f2pのページ遷移が取れているようだ。
192.168.100.200 - - [1/Jan/2009:10:14:33 JST] "GET /login/clear HTTP/1.1" 302 117 http://servername/f2p/entry/list -> /login/clear 192.168.100.200 - - [1/Jan/2009:10:14:33 JST] "GET /login HTTP/1.1" 200 839 http://servername/f2p/entry/list -> /login 192.168.100.200 - - [1/Jan/2009:10:14:48 JST] "POST /login/authenticate HTTP/1.1" 302 117 http://servername/f2p/login -> /login/authenticate 192.168.100.200 - - [1/Jan/2009:10:14:49 JST] "GET /entry HTTP/1.1" 302 120 http://servername/f2p/login -> /entry 192.168.100.200 - - [1/Jan/2009:10:14:49 JST] "GET /entry/list HTTP/1.1" 200 3622 http://servername/f2p/login -> /entry/list 192.168.100.200 - - [1/Jan/2009:10:15:35 JST] "GET /entry/list?num=20&start=20 HTTP/1.1" 200 5255 http://servername/f2p/entry/list -> /entry/list?num=20&start=20
2009/2/21追記 Syslogは英語だけしか受けつけないという問題
RoRのログって詳細だから、入力された英語以外の言語のデータやコードに関連する情報が漏れちゃう可能性があると指摘されました。確かにデバッグ用途には問題があるような気がする。
受け手をsyslog-ngにしたら違うのか？それともSystemLoggerが情報を落としちゃうのかは調べないと。
(さらに追記：syslog-ngも試してみているので、設定例を追加しました。以下、すべてのpriorityをログした場合
Feb 21 10:04:33 s_local@www f2p[16777]: Processing EntryController#list (for xxx.xxx.xxx.xx at 2009-02-21 10:04:33) [GET]
Feb 21 10:04:33 s_local@www f2p[16777]: Session ID: ******************
Feb 21 10:04:33 s_local@www f2p[16777]: User Load (0.4ms) SELECT * FROM "users" WHERE ("users"."id" = 5)
Feb 21 10:04:33 s_local@www f2p[16777]: Profile Load (0.5ms) SELECT * FROM "profiles" WHERE ("profiles".user_id = 5) LIMIT 1
Feb 21 10:04:33 s_local@www f2p[16777]: FriendFeed::APIClient is accessing to https://friendfeed.com/api/feed/home
Feb 21 10:04:34 s_local@www f2p[16777]: elapsed: 0.8974 [sec]
Feb 21 10:04:34 s_local@www f2p[16777]: Rendering template within layouts/entry
Feb 21 10:04:34 s_local@www f2p[16777]: Rendering entry/list
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (4.0ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.5ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.3ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (0.8ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.2ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (2.3ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (12.1ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.2ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (0.7ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.2ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.6ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (9.4ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_comment (1.6ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (5.5ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (2.9ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.4ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (4.1ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.6ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (1.2ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.3ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.4ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.6ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.4ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.4ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.7ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.5ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.5ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Rendered entry/_entry (3.6ms)
Feb 21 10:04:34 s_local@www f2p[16777]: Completed in 1152ms (View: 107, DB: 2) | 200 OK http://servername/entry/list
これにほぼ対応する生のRailsのログは、エスケープシークエンスか制御コードのようなものが含まれていて、そういった情報は抜け落ちてしまうようです。日本語などが含まれていたらどうなるかは、まだ確認できていません。（2009/3/2追記：UTF-8のデータは問題なく記録できるようでした）
Processing EntryController#list (for ***.***.***.** at 2009-02-21 09:40:35) [GET
]
Session ID: *****************************
Parameters: {"num"=>"20", "start"=>"20"}
^[[4;35;1mUser Load (0.4ms)^[[0m ^[[0mSELECT * FROM "users" WHERE ("users"."
id" = 5) ^[[0m
FriendFeed::APIClient is accessing to https://friendfeed.com/api/feed/home
elapsed: 0.935519 [sec]
Rendering template within layouts/entry
Rendering entry/list
Rendered entry/_entry (4.0ms)
^[[4;36;1mProfile Load (0.6ms)^[[0m ^[[0;1mSELECT * FROM "profiles" WHERE ("
profiles".user_id = 5) LIMIT 1^[[0m
Rendered entry/_entry (3.5ms)
Rendered entry/_entry (1.3ms)
Rendered entry/_entry (3.5ms)
Rendered entry/_entry (3.4ms)
Rendered entry/_entry (4.2ms)
Rendered entry/_entry (4.8ms)
Rendered entry/_entry (4.2ms)
Rendered entry/_entry (2.9ms)
Rendered entry/_entry (2.9ms)
Rendered entry/_comment (1.3ms)
Rendered entry/_comment (0.7ms)
Rendered entry/_comment (1.2ms)
Rendered entry/_comment (1.5ms)
Rendered entry/_entry (11.1ms)
Rendered entry/_entry (4.0ms)
Rendered entry/_entry (3.7ms)
Rendered entry/_entry (3.6ms)
Rendered entry/_entry (3.6ms)
Rendered entry/_entry (5.0ms)
Completed in 1176ms (View: 99, DB: 1) | 200 OK http://servername/entry/list?num=20&start=20
2009/2/21追記：rotationはお忘れなく
最低でもアクセスログ以上のサイズのデータなので、人気のあるサイトなら、うまくローテーションしたり消去する設定をlogrotate.d/以下で指定しておかないとハマるでしょう。
ちなみに、インストールする際には、一応syslog-ng用の設定はされるのですが、毎週のローテーションで、52週分のデータが圧縮されて保存される設定です。気をつけないと、ディスク容量を圧迫するかも。
