読者です 読者をやめる 読者になる 読者になる

Rails初心に還った人のメモ。f2p(ffp)からsyslogを出させてみる(修正有)

SyslogLogger
参考記事:Railsアプリケーションのログをsyslogに記録する方法 - Hello, world! - s21g
上の記事のまんまだと、f2p/log/(development|production).log に出てくるのと一緒(追記註:実は英語以外の情報は失われることがあるらしい)の詳細なログになっちゃうので、あえて infoのレベル以上のものだけ採取してみる。(OSは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週分のデータが圧縮されて保存される設定です。気をつけないと、ディスク容量を圧迫するかも。