ロガーを設定してみる
TweetPosted on Thursday Jan 23, 2014 at 04:32PM in Technology
環境
- WildFly8.0.0CR1
jboss-cliからやる方法
CLIの管理コマンドjboss-cliを起動しconnectした後に打つコマンドです
コンソールのログレベルをTRACEレベルにする
/subsystem=logging/console-handler=CONSOLE:change-log-level(level=TRACE)
org.hibernate.SQLのロガーをTRACEレベルで作る
/subsystem=logging/logger=org.hibernate.SQL:add(level=TRACE)
この2つをやると取り急ぎHibernateのSQLが出るようになります。
コマンドを打つとすぐに設定が反映されてログが出るようになります。再起動はいりません。便利だ。
コンソールのログレベルを確認
/subsystem=logging/console-handler=CONSOLE:read-resource
追加したロガーを確認
/subsystem=logging/logger=org.hibernate.SQL:read-resource
ロガーを削除
/subsystem=logging/logger=org.hibernate.SQL:remove
ロガーを一覧表示
ls /subsystem=logging/logger
ロガーのログレベルを変更
org.hibernate.SQLのログレベルをTRACEに変更
/subsystem=logging/logger=org.hibernate.SQL:change-log-level(level=TRACE)
ファイルハンドラの設定
- ここからはWildFly8.0.0Finalで実験。多分CR1でも同じだと思うけど
ログ出力用サーブレット
- こんな感じのログ出力サーブレットをデプロイして実験してみる
package logger;
import java.io.IOException;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
@WebServlet("/")
public class LogServlet extends HttpServlet {
private static final java.util.logging.Logger JUL_LOGGER1 = java.util.logging.Logger.getLogger("hoge.logger1");
private static final org.slf4j.Logger SLF4J_LOGGER1 = org.slf4j.LoggerFactory.getLogger("hoge.logger1");
private static final java.util.logging.Logger JUL_LOGGER2 = java.util.logging.Logger.getLogger("hoge.logger2");
private static final org.slf4j.Logger SLF4J_LOGGER2 = org.slf4j.LoggerFactory.getLogger("hoge.logger2");
protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
JUL_LOGGER1.info("JUL_LOGGER1.info()");
SLF4J_LOGGER1.info("SLF4J_LOGGER1.info()");
JUL_LOGGER2.info("JUL_LOGGER2.info()");
SLF4J_LOGGER2.info("SLF4J_LOGGER2.info()");
}
}
設定
- jboss-cliを使う
ファイルハンドラ作成
/subsystem=logging/file-handler=HOGE_LOGGER1:add(level=INFO, file={"relative-to"=>"jboss.server.log.dir", "path"=>"HOGE_LOGGER1.log"}, append=true, autoflush=true)
ロガーをファイルハンドラを指定して作成
/subsystem=logging/logger=hoge.logger1:add(use-parent-handlers=false,handlers=["HOGE_LOGGER1"])
この状態でサーブレットにアクセスすると
kyle-no-MacBook:log kyle$ pwd /Users/kyle/apps/wildfly-8.0.0.Final/standalone/log kyle-no-MacBook:log kyle$ cat HOGE_LOGGER1.log 08:30:31,672 INFO [hoge.logger1] (default task-11) JUL_LOGGER1.info() 08:30:31,672 INFO [hoge.logger1] (default task-11) SLF4J_LOGGER1.info() kyle-no-MacBook:log kyle$
- この例だとEclipseのコンソールやserver.logには出なくなる。hoge.logger2の出力だけ残る:
08:30:31,672 INFO [hoge.logger2] (default task-11) JUL_LOGGER2.info() 08:30:31,673 INFO [hoge.logger2] (default task-11) SLF4J_LOGGER2.info()
- ハンドラには、他にも日時でローテートできるファイルハンドラや、サイズでローテートできるファイルハンドラ、syslogに転送するハンドラなどがある[3]
- logbackほど豊富ではないが、ほとんどの局面で問題なさそうな品揃えな気はする
server.logには出したくないけどコンソールには出したい
- こうするとコンソールに出るようになる
/subsystem=logging/logger=hoge.logger1:assign-handler(name=CONSOLE)
- コンソールの出力
08:40:33,090 INFO [hoge.logger1] (default task-14) JUL_LOGGER1.info() 08:40:33,090 INFO [hoge.logger1] (default task-14) SLF4J_LOGGER1.info() 08:40:33,090 INFO [hoge.logger2] (default task-14) JUL_LOGGER2.info() 08:40:33,091 INFO [hoge.logger2] (default task-14) SLF4J_LOGGER2.info()
- HOGE_LOGGER1.log
08:40:33,090 INFO [hoge.logger1] (default task-14) JUL_LOGGER1.info() 08:40:33,090 INFO [hoge.logger1] (default task-14) SLF4J_LOGGER1.info()
- server.log
2014-03-06 08:40:33,090 INFO [hoge.logger2] (default task-14) JUL_LOGGER2.info() 2014-03-06 08:40:33,091 INFO [hoge.logger2] (default task-14) SLF4J_LOGGER2.info()
日時でローテートさせたい
- periodic-rotating-file-handlerを使うとできる
- server.log用にデフォルトで作られているハンドラの設定はこんな感じになっている
[standalone@localhost:9990 /] /subsystem=logging/periodic-rotating-file-handler=FILE:read-resource
{
"outcome" => "success",
"result" => {
"append" => true,
"autoflush" => true,
"enabled" => true,
"encoding" => undefined,
"file" => {
"relative-to" => "jboss.server.log.dir",
"path" => "server.log"
},
"filter" => undefined,
"filter-spec" => undefined,
"formatter" => "%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n",
"level" => "ALL",
"name" => "FILE",
"named-formatter" => "PATTERN",
"suffix" => ".yyyy-MM-dd"
}
}
- 上を参考に分単位でローテートするファイルハンドラを作ってみる
/subsystem=logging/periodic-rotating-file-handler=HOGE_LOGGER2:add( \
append=true, \
autoflush=true, \
enabled=true, \
file= {"relative-to"=>"jboss.server.log.dir", "path"=>"HOGE_LOGGER2.log"}, \
formatter= "%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n", \
level=INFO, \
named-formatter=PATTERN, \
suffix=".yyyy-MM-dd_HHmm")
- hoge.logger2ロガーを作る
- HOGE_LOGGER2とCONSOLEをハンドラにする
/subsystem=logging/logger=hoge.logger2:add(use-parent-handlers=false,handlers=["HOGE_LOGGER2", "CONSOLE"])
- こんな感じになる
kyle-no-MacBook:log kyle$ ls -l HOGE_LOGGER2* -rw-r--r--+ 1 kyle staff 164 3 6 09:01 HOGE_LOGGER2.log -rw-r--r--+ 1 kyle staff 0 3 6 08:54 HOGE_LOGGER2.log.2014-03-06_0854 -rw-r--r--+ 1 kyle staff 822 3 6 08:58 HOGE_LOGGER2.log.2014-03-06_0858 -rw-r--r--+ 1 kyle staff 328 3 6 08:59 HOGE_LOGGER2.log.2014-03-06_0859 kyle-no-MacBook:log kyle$ cat HOGE_LOGGER2.log.2014-03-06_0858 2014-03-06 08:58:15,099 INFO [hoge.logger2] (default task-15) JUL_LOGGER2.info() 2014-03-06 08:58:15,101 INFO [hoge.logger2] (default task-15) SLF4J_LOGGER2.info() 2014-03-06 08:58:18,526 INFO [hoge.logger2] (default task-1) JUL_LOGGER2.info() 2014-03-06 08:58:18,526 INFO [hoge.logger2] (default task-1) SLF4J_LOGGER2.info() 2014-03-06 08:58:19,645 INFO [hoge.logger2] (default task-2) JUL_LOGGER2.info() 2014-03-06 08:58:19,645 INFO [hoge.logger2] (default task-2) SLF4J_LOGGER2.info() 2014-03-06 08:58:20,461 INFO [hoge.logger2] (default task-3) JUL_LOGGER2.info() 2014-03-06 08:58:20,461 INFO [hoge.logger2] (default task-3) SLF4J_LOGGER2.info() 2014-03-06 08:58:22,126 INFO [hoge.logger2] (default task-4) JUL_LOGGER2.info() 2014-03-06 08:58:22,127 INFO [hoge.logger2] (default task-4) SLF4J_LOGGER2.info() kyle-no-MacBook:log kyle$ cat HOGE_LOGGER2.log.2014-03-06_0859 2014-03-06 08:59:03,932 INFO [hoge.logger2] (default task-5) JUL_LOGGER2.info() 2014-03-06 08:59:03,933 INFO [hoge.logger2] (default task-5) SLF4J_LOGGER2.info() 2014-03-06 08:59:04,258 INFO [hoge.logger2] (default task-6) JUL_LOGGER2.info() 2014-03-06 08:59:04,258 INFO [hoge.logger2] (default task-6) SLF4J_LOGGER2.info() kyle-no-MacBook:log kyle$ cat HOGE_LOGGER2.log 2014-03-06 09:01:39,835 INFO [hoge.logger2] (default task-7) JUL_LOGGER2.info() 2014-03-06 09:01:39,836 INFO [hoge.logger2] (default task-7) SLF4J_LOGGER2.info() kyle-no-MacBook:log kyle$
ファイルサイズでローテートさせたい
- size-rotating-file-handlerを使えば可能
- 保持する古いログの上限を設定すると、上限を超えた古いログを自動で削除してくれる
- ハンドラの作成はこんな感じ。サイズ2Kでローテート、5つを超えたら削除
/subsystem=logging/size-rotating-file-handler=SRFH1:add( \
append=true, \
autoflush=true, \
enabled=true, \
file= {"relative-to"=>"jboss.server.log.dir", "path"=>"SRFH1.log"}, \
formatter= "%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n", \
level=INFO, \
named-formatter=PATTERN, \
rotate-size="2k", \
max-backup-index="5" )
- hoge.logger1にアサインする
/subsystem=logging/logger=hoge.logger1:assign-handler(name=SRFH1)
- さっきのサーブレットのリロードをしばし連打するとこんな感じになる
kyle-no-MacBook:log kyle$ pwd /Users/kyle/apps/wildfly-8.0.0.Final/standalone/log kyle-no-MacBook:log kyle$ ls -l SRFH* -rw-r--r--+ 1 kyle staff 746 3 6 10:44 SRFH1.log -rw-r--r--+ 1 kyle staff 2056 3 6 10:44 SRFH1.log.1 kyle-no-MacBook:log kyle$ cat SRFH1.log.1 2014-03-06 10:44:18,330 INFO [hoge.logger1] (default task-15) JUL_LOGGER1.info() 2014-03-06 10:44:18,330 INFO [hoge.logger1] (default task-15) SLF4J_LOGGER1.info() 2014-03-06 10:44:22,966 INFO [hoge.logger1] (default task-1) JUL_LOGGER1.info() 2014-03-06 10:44:22,967 INFO [hoge.logger1] (default task-1) SLF4J_LOGGER1.info() 2014-03-06 10:44:23,132 INFO [hoge.logger1] (default task-2) JUL_LOGGER1.info() 2014-03-06 10:44:23,133 INFO [hoge.logger1] (default task-2) SLF4J_LOGGER1.info() 2014-03-06 10:44:23,268 INFO [hoge.logger1] (default task-3) JUL_LOGGER1.info() 2014-03-06 10:44:23,268 INFO [hoge.logger1] (default task-3) SLF4J_LOGGER1.info() 2014-03-06 10:44:23,391 INFO [hoge.logger1] (default task-4) JUL_LOGGER1.info() 2014-03-06 10:44:23,392 INFO [hoge.logger1] (default task-4) SLF4J_LOGGER1.info() 2014-03-06 10:44:25,137 INFO [hoge.logger1] (default task-5) JUL_LOGGER1.info() 2014-03-06 10:44:25,138 INFO [hoge.logger1] (default task-5) SLF4J_LOGGER1.info() 2014-03-06 10:44:25,315 INFO [hoge.logger1] (default task-6) JUL_LOGGER1.info() 2014-03-06 10:44:25,316 INFO [hoge.logger1] (default task-6) SLF4J_LOGGER1.info() 2014-03-06 10:44:25,451 INFO [hoge.logger1] (default task-7) JUL_LOGGER1.info() 2014-03-06 10:44:25,451 INFO [hoge.logger1] (default task-7) SLF4J_LOGGER1.info() 2014-03-06 10:44:25,574 INFO [hoge.logger1] (default task-8) JUL_LOGGER1.info() 2014-03-06 10:44:25,574 INFO [hoge.logger1] (default task-8) SLF4J_LOGGER1.info() 2014-03-06 10:44:26,623 INFO [hoge.logger1] (default task-9) JUL_LOGGER1.info() 2014-03-06 10:44:26,623 INFO [hoge.logger1] (default task-9) SLF4J_LOGGER1.info() 2014-03-06 10:44:26,767 INFO [hoge.logger1] (default task-10) JUL_LOGGER1.info() 2014-03-06 10:44:26,767 INFO [hoge.logger1] (default task-10) SLF4J_LOGGER1.info() 2014-03-06 10:44:26,901 INFO [hoge.logger1] (default task-11) JUL_LOGGER1.info() 2014-03-06 10:44:26,902 INFO [hoge.logger1] (default task-11) SLF4J_LOGGER1.info() 2014-03-06 10:44:27,048 INFO [hoge.logger1] (default task-12) JUL_LOGGER1.info() kyle-no-MacBook:log kyle$ cat SRFH1.log 2014-03-06 10:44:27,048 INFO [hoge.logger1] (default task-12) SLF4J_LOGGER1.info() 2014-03-06 10:44:27,184 INFO [hoge.logger1] (default task-13) JUL_LOGGER1.info() 2014-03-06 10:44:27,185 INFO [hoge.logger1] (default task-13) SLF4J_LOGGER1.info() 2014-03-06 10:44:27,306 INFO [hoge.logger1] (default task-14) JUL_LOGGER1.info() 2014-03-06 10:44:27,307 INFO [hoge.logger1] (default task-14) SLF4J_LOGGER1.info() 2014-03-06 10:44:27,452 INFO [hoge.logger1] (default task-15) JUL_LOGGER1.info() 2014-03-06 10:44:27,453 INFO [hoge.logger1] (default task-15) SLF4J_LOGGER1.info() 2014-03-06 10:44:27,599 INFO [hoge.logger1] (default task-1) JUL_LOGGER1.info() 2014-03-06 10:44:27,599 INFO [hoge.logger1] (default task-1) SLF4J_LOGGER1.info() kyle-no-MacBook:log kyle$
- さらに連打するとこうなる
kyle-no-MacBook:log kyle$ ls -l SRFH* -rw-r--r--+ 1 kyle staff 1652 3 6 10:46 SRFH1.log -rw-r--r--+ 1 kyle staff 2058 3 6 10:46 SRFH1.log.1 -rw-r--r--+ 1 kyle staff 2056 3 6 10:46 SRFH1.log.2 -rw-r--r--+ 1 kyle staff 2061 3 6 10:46 SRFH1.log.3 -rw-r--r--+ 1 kyle staff 2061 3 6 10:46 SRFH1.log.4 -rw-r--r--+ 1 kyle staff 2063 3 6 10:46 SRFH1.log.5 kyle-no-MacBook:log kyle$ head SRFH1.log.5 2014-03-06 10:46:17,340 INFO [hoge.logger1] (default task-7) SLF4J_LOGGER1.info() 2014-03-06 10:46:17,516 INFO [hoge.logger1] (default task-8) JUL_LOGGER1.info() 2014-03-06 10:46:17,517 INFO [hoge.logger1] (default task-8) SLF4J_LOGGER1.info() 2014-03-06 10:46:17,653 INFO [hoge.logger1] (default task-9) JUL_LOGGER1.info() 2014-03-06 10:46:17,653 INFO [hoge.logger1] (default task-9) SLF4J_LOGGER1.info() 2014-03-06 10:46:17,789 INFO [hoge.logger1] (default task-10) JUL_LOGGER1.info() 2014-03-06 10:46:17,789 INFO [hoge.logger1] (default task-10) SLF4J_LOGGER1.info() 2014-03-06 10:46:17,952 INFO [hoge.logger1] (default task-11) JUL_LOGGER1.info() 2014-03-06 10:46:17,952 INFO [hoge.logger1] (default task-11) SLF4J_LOGGER1.info() 2014-03-06 10:46:18,085 INFO [hoge.logger1] (default task-12) JUL_LOGGER1.info() kyle-no-MacBook:log kyle$
- java.util.loggingちっくな感じ。ちゃんと古いのは消えている
- 書いてから気づいたけどnamed-formatterとformatterはどっちかだけでいいかも
syslogにログを飛ばしてみる
- OS Xは10.9.2
- TCPにも出来るかもしれないけどとりあえずUDPでやってみる
OS Xのsyslogdの設定
- ソケット経由でログの送信を受け付けるようにする
- syslogdのplistの編集
kyle-no-MacBook:LaunchDaemons kyle$ sudo /usr/libexec/PlistBuddy /System/Library/LaunchDaemons/com.apple.syslogd.plist Command: add :Sockets:NetworkListener dict Command: add :Sockets:NetworkListener:SockServiceName string syslog Command: add :Sockets:NetworkListener:SockType string dgram Command: save Saving... Command: quit
- syslog.confに適当なテスト用facilityを追加
local1.* /var/log/hoge1.log
- syslogdの再起動
kyle-no-MacBook:LaunchDaemons kyle$ sudo launchctl unload com.apple.syslogd.plist kyle-no-MacBook:LaunchDaemons kyle$ sudo launchctl load com.apple.syslogd.plist kyle-no-MacBook:LaunchDaemons kyle$ sudo lsof -i:514 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME launchd 1 root 39u IPv4 0xf0749ee857f40f93 0t0 UDP *:syslog launchd 1 root 147u IPv6 0xf0749ee836545ceb 0t0 UDP *:syslog syslogd 56930 root 4u IPv4 0xf0749ee857f40f93 0t0 UDP *:syslog syslogd 56930 root 5u IPv6 0xf0749ee836545ceb 0t0 UDP *:syslog kyle-no-MacBook:LaunchDaemons kyle$
- loggerからログを出してみる。ソケット経由で送る方法はわからんかった
kyle-no-MacBook:etc kyle$ logger -p local1.notice hogehoge kyle-no-MacBook:etc kyle$ cat /var/log/hoge1.log Mar 6 11:19:24 kyle-no-MacBook.local kyle[57062]: hogehoge kyle-no-MacBook:etc kyle$
WildFly側の設定
- まずハンドラを作る
- [6]に若干説明がある
- facilityはsyslog.confの書き方と若干異なる。一覧は[6]にある
- hostnameってのはログの送信元ホスト名らしい
- server-addressが送信先ホスト名
/subsystem=logging/syslog-handler=SYSLOG1:add( \ app-name="hogeapp", \ facility="local-use-1", \ hostname="kyle-wildfly", \ level=INFO, \ server-address="localhost")
- hoge.logger1にアサイン
/subsystem=logging/logger=hoge.logger1:assign-handler(name=SYSLOG1)
- サーブレットをリロードすると
kyle-no-MacBook:log kyle$ tail -f /var/log/hoge1.log Mar 6 11:19:24 kyle-no-MacBook.local kyle[57062]: hogehoge Mar 6 11:29:15 1 2014-03-06T11: 29:15.653+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - JUL_LOGGER1.info() Mar 6 11:29:15 1 2014-03-06T11: 29:15.670+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - SLF4J_LOGGER1.info() Mar 6 11:30:03 1 2014-03-06T11: 30:03.549+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - JUL_LOGGER1.info() Mar 6 11:30:03 1 2014-03-06T11: 30:03.549+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - SLF4J_LOGGER1.info() Mar 6 11:30:05 1 2014-03-06T11: 30:05.327+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - JUL_LOGGER1.info() Mar 6 11:30:05 1 2014-03-06T11: 30:05.327+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - SLF4J_LOGGER1.info() Mar 6 11:30:05 1 2014-03-06T11: 30:05.765+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - JUL_LOGGER1.info() Mar 6 11:30:05 1 2014-03-06T11: 30:05.766+09:00 kyle-wildfly hogeapp 5435 hoge.logger1 - SLF4J_LOGGER1.info()
- 出力フォーマットはもう一種類あるみたいなので変えてみる
/subsystem=logging/syslog-handler=SYSLOG1:write-attribute(name="syslog-format", value="RFC3164")
- 出力日時が一個だけになる
Mar 6 11:33:41 kyle-wildfly hogeapp[5435]: JUL_LOGGER1.info() Mar 6 11:33:41 kyle-wildfly hogeapp[5435]: SLF4J_LOGGER1.info()
- 5435って何の数字だろう。WildFlyのPIDかと思ったけど違うし
- シビリティとかロガー名が欠落しているのが残念な気はする
org.jboss.logmanager.handlers.SyslogHandlerを試してみる
- [3]によるとsyslog-handlerよりこっちの方が機能が多いらしい
- そのうちsyslog-handlerにマージされるらしい
- ハンドラを作る。設定はpropertiesに書くんだけど資料っぽいものがないので[7]のソースを見てsetterの名前から類推した
/subsystem=logging/custom-handler=SYSLOG2:add( \
class="org.jboss.logmanager.handlers.SyslogHandler", \
module="org.jboss.logmanager", \
named-formatter=PATTERN, \
level=INFO, \
properties={ \
appName="hogeapp", \
hostname="kyle-wildfly", \
serverHostname="localhost", \
facility="LOCAL_USE_1", \
syslogType="RFC3164" })
- SYSLOG1のアサインを解除してSYSLOG2をアサイン
/subsystem=logging/logger=hoge.logger1:unassign-handler(name=SYSLOG1) /subsystem=logging/logger=hoge.logger1:assign-handler(name=SYSLOG2)
- こんな感じ。ロガー名とシビリティが出た。#012って何だろう
Mar 6 12:15:24 kyle-wildfly hogeapp[5435]: 2014-03-06 12:15:24,646 INFO [hoge.logger1] (default task-11) JUL_LOGGER1.info()#012 Mar 6 12:15:24 kyle-wildfly hogeapp[5435]: 2014-03-06 12:15:24,648 INFO [hoge.logger1] (default task-11) SLF4J_LOGGER1.info()#012 Mar 6 12:15:25 kyle-wildfly hogeapp[5435]: 2014-03-06 12:15:25,144 INFO [hoge.logger1] (default task-12) JUL_LOGGER1.info()#012 Mar 6 12:15:25 kyle-wildfly hogeapp[5435]: 2014-03-06 12:15:25,145 INFO [hoge.logger1] (default task-12) SLF4J_LOGGER1.info()#012
- #012を消すべくフォーマットをいじってみる
- いったんSYSLOG2を消す
/subsystem=logging/logger=hoge.logger1:unassign-handler(name=SYSLOG2) /subsystem=logging/custom-handler=SYSLOG2:remove
- フォーマットいじって作り直し
/subsystem=logging/custom-handler=SYSLOG2:add( \
class="org.jboss.logmanager.handlers.SyslogHandler", \
module="org.jboss.logmanager", \
formatter="%-5p [%c] (%t) %s", \
level=INFO, \
properties={ \
appName="hogeapp", \
hostname="kyle-wildfly", \
serverHostname="localhost", \
facility="LOCAL_USE_1", \
syslogType="RFC3164" })
/subsystem=logging/logger=hoge.logger1:assign-handler(name=SYSLOG2)
- こうなる。シビリティとロガー名も出てるしこれでいいかな。
Mar 6 13:00:20 kyle-wildfly hogeapp[5435]: INFO [hoge.logger1] (default task-10) JUL_LOGGER1.info() Mar 6 13:00:20 kyle-wildfly hogeapp[5435]: INFO [hoge.logger1] (default task-10) SLF4J_LOGGER1.info()
- ちなみにformatterの書き方はlog4jと同じらしい[8]
- 例外とか最大長も考慮するとRFC3164形式ならこんな感じがいいかも
/subsystem=logging/custom-handler=SYSLOG6:add( \
class="org.jboss.logmanager.handlers.SyslogHandler", \
module="org.jboss.logmanager", \
formatter="%-5p [%c] (%t) %s%e", \
level=INFO, \
properties={ \
appName="hogeapp", \
hostname="kyle-wildfly", \
serverHostname="localhost", \
facility="LOCAL_USE_1", \
truncate=false, \
maxLength=1024, \
syslogType="RFC3164" })
/subsystem=logging/logger=hoge.logger1:assign-handler(name=SYSLOG6)
- ログはこんな感じ
Mar 8 10:17:02 kyle-wildfly hogeapp[91739]: INFO [hoge.logger1] (default task-1) 0-1199: 0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567 Mar 8 10:17:02 kyle-wildfly hogeapp[91739]: 89012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789 Mar 8 10:17:02 kyle-wildfly hogeapp[91739]: INFO [hoge.logger1] (default task-1) exception logging test: java.lang.AssertionError: test#012#011at logger.LogServlet.doGet(LogServlet.java:22)#012#011at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)#012#011at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)#012#011at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)#012#011at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61)#012#011at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)#012#011at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)#012#011at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)#012#011at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociati Mar 8 10:17:02 kyle-wildfly hogeapp[91739]: onHandler.java:113)#012#011at io.undertow.security.handlers.AuthenticationCallHandler.handleRequest(AuthenticationCallHandler.java:52)#012#011at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45)#012#011at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:61)#012#011at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70)#012#011at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76)#012#011at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)#012#011at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)#012#011at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)#012 Mar 8 10:17:02 kyle-wildfly hogeapp[91739]: #011at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)#012#011at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:240)#012#011at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:227)#012#011at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:73)#012#011at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:146)#012#011at io.undertow.server.Connectors.executeRootHandler(Connectors.java:168)#012#011at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:687)#012#011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)#012#011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)#012#011at java.lang.Thread.run(Thread.java:744)#012
- タブや改行がエスケープ(#011と#012)されていたり、長いログが分割されていたりするけどちゃんと抜け漏れなく出てる
- escapeEnabled=“false” にするとエスケープされなくなる
- けどこれやるとUDPでログを送信する場合は、複数行のメッセージが欠ける[10]
- RFC5424形式の方が最大長が長かったりするみたいなので、Linuxとかでまた調べる。ソース見るとSSLやTCPでの送信にも対応しているみたい
- 何故か日本語とかマルチバイト文字が正しく出ない。encoding=“UTF-8” とか入れてみたけど駄目だった。なぜだろう
- 少しソースを追っかけてみると、charをbyte[]に分ける処理とかがあってそのあたりで何かがおかしくなってるようだった。
- 暇があったらプルリクエスト送りたいけど大変そうなのでまたそのうち見てみる
- issueは[11]に上げてプルリクエストも送ってみた
org.apache.log4j.net.SMTPAppenderを使ってみる
ハンドラの設定
- GMail経由でSSLで認証付きで送る方法。詳細な設定は[12][13]あたりを参照
- APサーバに設定したSessionをJNDIで指定できればいいんだけどそういうのはないみたい
/subsystem=logging/custom-handler=LOG4J_SMTP:add( \
class="org.apache.log4j.net.SMTPAppender", \
module="org.apache.log4j", \
formatter="%-5p [%c] (%t) %s%e", \
level=INFO, \
properties={ \
From="jane.doe@gmail.example.com", \
LocationInfo=true, \
SMTPDebug=true, \
SMTPHost="smtp.gmail.com", \
SMTPPort=465, \
SMTPProtocol="smtps", \
SMTPUsername="jane.doe@gmail.example.com", \
SMTPPassword="***", \
Subject="error mail subject", \
To="jane.doe@icloud.example.com", \
BufferSize=256 })
- propertiesにSMTPDebug=trueを追加するとログに通信内容が出るので問題解決にはよいかも
ロガーにハンドラをアサイン
/subsystem=logging/logger=hoge.logger1:assign-handler(name=LOG4J_SMTP)
お試し用サーブレット
- こんな感じでログ出してみる
protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
JUL_LOGGER1.info("JUL_LOGGER1.info()");
SLF4J_LOGGER1.error("にほんご えらー");
}
こんなメールがくる
- 日本語出せない問題は少し前に直ったみたい。
本番環境だとどんな感じが良いか
- ファイルハンドラ系で素直に吐き出しておいて、fluentdとかのログ収集の仕組みを別に入れるのが、モダンな感じで良いんじゃなかろうかと思う
- syslog絡めてやるのが良いかなと思うが
- SyslogHandlerで日本語が出せないのがつらい。一応issueは上げておいたけど[11]。
- Log4Jのsyslogappenderは、一部の文言が欠けるのがつらい
- size-rotating-file-handlerとかでローカルに出しつつ（こいつは古いログのパージもやってくれるので）、syslogにも出して、最終的にはどこかのログサーバに集約するとか
org.jboss.logmanager.handlers.SyslogHandlerはExceptionをログに出してくれないようだ。嘘付いてた。formatterに “%e” を設定すると出る。- 実はcustom-loggerではLog4JのAppenderも使えるので、log4jのsyslog用Appenderを使うかと思って試してみたら、確かに例外もログに出るんだけど、何故かスタックトレースやメッセージの一部が欠ける謎の現象が現れるので、あんまり良くない
- あとlog4jのSMTPAppenderのメール通知は状況によっては便利だと思う。WildFlyなら別にjar持ってきたりする必要も無くCLIから設定するだけで使える。
気になる事
- syslogに出すとpidらしきところに5435と表示されるんだが、そんなプロセスは動いてない
kyle-no-MacBook:etc kyle$ ps -Af | grep java | grep 5435 501 54356 42731 0 8:01AM ?? 0:32.26 /Library/Java/JavaVirtualMachines/jdk1.7.0_51.jdk/Contents/Home/bin/java -Dprogram.name=JBossTools: WildFly 8.0.0...
- WildFlyは54356なんだけど一番下の桁が欠けてるとかあり得るのだろうか
- 調べたら欠けてた[9]
参考文献
- Logging Configuration - WildFly 8 - Project Documentation Editor
- How To - WildFly 8 - Project Documentation Editor
- Handlers - WildFly 8 - Project Documentation Editor
- 11.5.6. Sample XML Configuration for a Size Log Handler
- Configuring JBoss AS 7.2 to log to syslog - Server Fault
- Logging Configuration - JBoss AS 7.2 - Project Documentation Editor
- GC: SyslogHandler - org.jboss.logmanager.handlers.SyslogHandler (.java) - GrepCode Class Source
- Customizing logging format in Jboss 7 AS | Community
- [LOGMGR-100] SyslogHandler.findPid() omitted the last digit of pid - JBoss Issue Tracker
- [syslog-ng] Extra Lines Truncated
- [LOGMGR-104] SyslogHandler doesn't handle multi-byte characters correctly - JBoss Issue Tracker
- SMTPAppender (Apache Log4j 1.2.17 API)
- Log4J徹底解説～ネットワーク系Appender
Tags: wildfly
