アクセスログの解析について

[shigel]

はじめまして、斉藤と申します。

Redmineの運用において、いつ、誰が、何をしたのかまで判別できるようにしたく、
ユーザが何をしたのか操作ログを採取したいと考えております。

調べてみたところ、チケットやプロジェクトを作成、削除などの更新系のアクセスを
した場合、production.log に、IP や authenticity_token と共に、リクエスト
パラメータ出力されますが、誰が実行しているかの紐付けが出来ません。

authenticity_token はセッションごとに発行されているようにも見えますが、
認証時と更新系のアクセスをした時では同一の authenticity_token が使用されて
おりません。

既存のログからの操作ログを取得する方法、もしくは既存のログと共にIDを出力する
方法など、良い方法はありませんでしょうか。


どなたか良い方法をご存じの方はいらっしゃませんでしょうか。

[fmkt]

こんにちは。

思いつく限りでは二通り。

1. 別途ロガーを仕込んで任意の出力を得る。
ApplicationController の before_filter にparamsから値を取れば、リクエストパラメータを取ることができ
ます。
またUser.currentでアクセスしてきたユーザの情報を取ることができるので、上記の値と合わせて好きなようにログに出力できると思います。

こんな感じで。

before_filter :access_logging
def access_logging
req_param = params.map {|key,value| "#{key} =>
#{value}"}.join(",")
message = "#{User.current.login}: #{req_param}"
log = Logger.new(File.join(RAILS_ROOT, "/log/access.log"),
"daily")
log.formatter = Logger::Formatter.new
log.info(message)
end


2. ログレベルを引き下げて運用してみる
アクセスのたびにデータベースのユーザテーブルへ問い合わせを行っているので、
ログレベルをdevelまで引き下げるとどのユーザがアクセスしてきたか標準のログにSQLが吐き出されてるのでわかります。
（ユーザIDとユーザ名のひも付けを別途しないといけませんが。。）
その他のSQLまで吐き出されてしまうので、フィルタを行う必要があると思います。
こちらの方法は眺めてる分にはいいですが、「ユーザが何をしたのか操作ログを採取したい」という要望に対しては手間がかかると思います。

以上、参考になれば。

[SAITOH, Shigel]

早速のご回答ありがとうございます。
大変参考になりました。

> 2. ログレベルを引き下げて運用してみる

まずは手っ取り早いこちらの方法で試したところ、SQLが出力されている
ことを確認いたしました。
パスワードもハッシュ化、もしくは非表示になっていたため、パスワードに
ついては問題なさそうです。
ただ、仰る通りそのまま出力していても運用には向かないですね。

> 1. 別途ロガーを仕込んで任意の出力を得る。

こちらについては最適なファイルが分からなかりませんでしたが、下記の
ファイルに追加してログが出力されることを確認いたしました。

/redmine/app/controllers/application_controller.rb

当方、Ruby自体慣れていないため、間違っていればご指摘願います。

ただし、こちらはパスワードがそのまま出力されてしまっていたので
セキュリティ面では課題が残ります。

下記のようにpasswordフィルターらしき部分を修正してみましたが、
ユーザパスワード変更時はログが出力されず、ログイン時には平文で
出力されてしまいました。

# before_filter :user_setup, :check_if_login_required, :set_localization
before_filter :user_setup, :check_if_login_required,
:set_localization, :access_logging
filter_parameter_logging :password
protect_from_forgery

これが解決出来れば1の方法がもっとも良さそうです。
引き続き調査いたします。

2011年5月10日9:36 fmkt <fmkt....@gmail.com>:

> --
> このメールは Google グループのグループ「Redmine Users (japanese)」の登録者に送られています。
> このグループに投稿するには、redmine-...@googlegroups.com にメールを送信してください。
> このグループから退会するには、redmine-users-...@googlegroups.com にメールを送信してください。
> 詳細については、http://groups.google.com/group/redmine-users-ja?hl=ja からこのグループにアクセスしてください。
>
>

[fmkt]

こんにちは。

パスワードのことすっかり抜けてました。

before_filter ではあく after_filter に変えて、
メソッド内で params.delete(:password) とかしてパラメータからパスワードの要素を消してしまえば
パスワード自体出力されなくなります。


after_filter :access_logging
def access_logging
params.delete(:password)

req_param = params.map {|key,value| "#{key} =>
#{value}"}.join(",")
message = "#{User.current.login}: #{req_param}"
log = Logger.new(File.join(RAILS_ROOT, "/log/access.log"),
"daily")
log.formatter = Logger::Formatter.new
log.info(message)
end

> 2011年5月10日9:36 fmkt <fmkt.ne...@gmail.com>:

[SAITOH, Shigel]

迅速なご確認ありがとうございます！

試したところ、無事ログ出力できるようになりました。
操作ログの採取はこれで一段落いたしました。
誠にありがとうございます。

最終的には出力したくないものを加えて下記のように致しました。

/redmine/app/controllers/application_controller.rb

after_filter :access_logging
def access_logging
params.delete(:password)

params.delete(:password_confirmation)
params.delete(:new_password)
params.delete(:new_password_confirmation)

req_param = params.map {|key,value| "#{key} => #{value}"}.join(",")
message = "#{User.current.login}: #{req_param}"
log = Logger.new(File.join(RAILS_ROOT, "/log/access.log"), "daily")
log.formatter = Logger::Formatter.new
log.info(message)
end

2011年5月10日13:46 fmkt <fmkt....@gmail.com>:

[fmkt]

こんにちは。

すみません、このままでは一つのプロセスの中でLogger.newを繰り返すので、
log.info(message) あとに log.close をしてIOを閉じないとメモリリークする気がします。

ちょっとご注意を。

On 5月10日, 午後7:01, "SAITOH, Shigel" <saitoh.shi...@gmail.com> wrote:
> 迅速なご確認ありがとうございます！
>
> 試したところ、無事ログ出力できるようになりました。
> 操作ログの採取はこれで一段落いたしました。
> 誠にありがとうございます。
>
> 最終的には出力したくないものを加えて下記のように致しました。
>
> /redmine/app/controllers/application_controller.rb
>
> after_filter :access_logging
> def access_logging
> params.delete(:password)
> params.delete(:password_confirmation)
> params.delete(:new_password)
> params.delete(:new_password_confirmation)
> req_param = params.map {|key,value| "#{key} => #{value}"}.join(",")
> message = "#{User.current.login}: #{req_param}"
> log = Logger.new(File.join(RAILS_ROOT, "/log/access.log"), "daily")
> log.formatter = Logger::Formatter.new
> log.info(message)
> end
>

> 2011年5月10日13:46 fmkt <fmkt.ne...@gmail.com>:

[SAITOH, Shigel]

何から何までありがとうございます。

ApplicationController はひとつのプロセスでオブジェクトを解放しないで
何度も利用されるんですね。
参考になります。

2011年5月11日9:59 fmkt <fmkt....@gmail.com>: