Javaに関する様々な情報をご紹介します。

Javaに関する様々な情報をご紹介します。
評価

0

log4j経由でsyslogに同じメッセージを出力する時に…

ちょっとこの掲示板で以下の質問をして良いのかどうかわからないのですが、質問します。
log4jのSyslogApenderを使用してのUnix上マシンでのsyslogに出力する時に、前回と同じ内容のメッセージを出力した場合(前回出力してから30秒経過して出力)、なぜか下記の出力になります。
Nov  9 11:56:39 usrA ccc: repeate test  
Nov  9 11:56:39 usrA last message repeated 1 times

『last message repeated 1 times』とは、syslogdのログの抑止をするための仕様です。
このメッセージが出るのは問題ないのですが、2回目の出力時刻が30秒たったにもかかわらず、前回と同じ時間を示しています。時刻を出力しているのは
syslogデーモンであり、syslogdが呼ばれた時刻を本来出力しています。

log4j経由ではなく、直接syslogdにログ要求を出した場合は、以下の出力なります。
Nov  9 11:56:39 usrA ccc: repeate test  
Nov  9 11:57:09 usrA last message repeated 1 times

いろいろ調べたのですが、原因の糸口すらわかりません。どんなに時間が経過しても前回と同じメッセージの場合、『last message repeated n times』が必ず出力されるので困っています。
なぜこのような現象になるのかわかる方がいましたら、ご教授願います。また回避方法がありましたら教えてください。

環境:
log4j1.2.12
JDK5.0
Solalis8.0

7

回答

83679

閲覧

7件の回答

評価

0

>syslogdが呼ばれた時刻を本来出力しています。

ということなので、log4j.xmlのConversionPatternには
%dが付いてないのだと思いますが、付いているとlog4jがフォーマットに時刻を設定し
発行側の時刻がそのまま採用されるので、確認がいるかもしれません。
ただlog4jの時刻は発生した時刻になるので、2回目は違う時刻になるはずなんですが・・

log4jの場合とCの場合で挙動が違うのであれば、syslogに送っているフォーマットに違いがあるはずなので、TCP/IPモニタで両者の送信フォーマットを比較すると問題が絞り込めるかもしれませんね。

評価

0

良く分かりませんが、その時刻はsyslogが付与している部分なんですか?
LoggingEventクラスの持っている時刻を標準出力へ出力するようにして、見てみるというのもありかも。

評価

0

>tamaさん,mioさん
回答ありがとうございます。
質問の内容について詳しく書いていなくて、すいません。

log4j設定ファイルのレイアウトパターンには,%dは入れていません。
ですがsyslogに送る要求メッセージとして時間も含まれてしまうので,前回と同じメッセージとして出力する検証にはなりません。

Dec 21 14:57:44 usrA 2006/12/21 14:57:44:ERROR SampleMain log4jTest
Dec 21 14:57:45 usrA 2006/12/21 14:57:45:ERROR SampleMain log4jTest
-------------------- ----------------------------------------------
・syslogdの出力       ・log4jでの出力メッセージ

ですが、この検証でちょっとしたことがわかりました。(たぶん)
ローカルマシン上(WindowsXP)でlog4jでのSyslogApender経由でログ要求を行い、Unixマシン上のsyslogに出力した結果は以下のようになりました。

Dec 21 14:55:44 usrA 2006/12/21 14:58:44:ERROR SampleMain log4jTest
(ローカルマシン上での時刻とUnixマシン上の時間差は3分です)
なので一番先頭の時刻は、syslogdが呼ばれたときに自分のマシン(Unixマシン)での現在時刻を見て出力してます。(確信はないですが...)
この問題って、log4jではなくsyslogデーモンの方に原因があるのかなと感じ始めました。


※log4jでどのようにsyslogにメッセージを出力しているかDEBUGモードでたどったのですが、
SyslogQuietWriterクラスのwriteメソッドでsyslogにメッセージを送っていました。
以下は、そのメソッドです。
  public
  void write(String string) {
    super.write("<"+(syslogFacility | level)+">" + string);
  }
変数stringには、メッセージ(上の例ではこの部分。『2006/12/21 14:58:44:ERROR SampleMain log4jTest』)が入っていました。
int型変数syslogFacility=144,level=3 
ですので、『<147>2006/12/21 14:58:44:ERROR SampleMain log4jTest』を送っています。
なんですかね、これ?⇒<147>


P・S UNIXマシン上で勝手にetherealなどをインストールすることが出来ないので、TCP/IPモニタで両者の送信フォーマットを比較する
ような検証はできませんでした。(ローカルマシン(WindowsXP)上でlog4j経由でunix上にメッセージを送る時にetherealで
取ったのですが、メッセージには<147>などはついておらず、特に原因になりそうなものは見つけられませんでした。比べる検証ができないので....)

評価

0

詳しく追ってませんが、144はSyslogAppenderの定数でしょう。
LOG_LOCAL2 = 18<<3なので、それに3をプラス(論理和)して147でしょう。
intの上位を送り先に、下位3ビットをレベルに使っていると思います。
syslogdでそこをみて判断するのでは?

評価

0

設定ファイル載せるの忘れました。
以下のようになってます。
log4j.category.test=ERROR, test
log4j.appender.test=org.apache.log4j.net.SyslogAppender
log4j.appender.test.Facility=local2
log4j.appender.test.SyslogHost=usrA
log4j.appender.test.layout=org.apache.log4j.PatternLayout
log4j.appender.test.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss}%-5p %C{1} %M %L %m%n

自分の見解ですが、おそらく144は、変数名がsyslogFacilityなだけに、LOG_LOCAL2=local2のファシリティだと思います。levelはレベルだけにログレベルかな?と思います。(先ほどlevel=3と記述したのですが4かと思います。曖昧です。嘘書いたらまずいのでこのような記述で勘弁して下さい)
ですので、ファシリティ(Facility)とプライオリティ(Priolity)をlog4j側で送ってsyslogdがそこを見ている形をとっているとおもいます。
私は、はじめlog4j経由有無でのsyslog出力の挙動が違っていたので、log4jがログ出力時間もsyslogdに送っているかと見解しましたが、この考えは全く覆されました。(ふりだしに戻った状態です)
syslogデーモンに聞いてみないとわからないみたいですね。
Unix上でethereaが使えたら......なにかわかりそうな気がする(泣)

評価

0

えっと<147>はmioさんがおっしゃっている通りのものです。
Facilityが29ビットPriorityが3ビットです。
18がlocal2なのでmioさんの計算通りです、ちなみに3のレベルはエラーです。

あと、ログが
>Dec 21 14:57:44 usrA 2006/12/21 14:57:44:ERROR SampleMain log4jTest
になっているのは、日付がsyslogの書式になっていないので、メッセージだと思われているからで
syslogが自ら時刻を設定しています。

syslogに時刻を送りたい場合ConversionPatternの時刻部分を
%d{MMM dd HH:mm:ss} %-5p以降同じ
にしてみてください、} %-5の空白は要ります。
書式上時刻部分はヘッダなので、この部分が変わってもメッセージ部分が同じならテストはできると思います。
Solalisの環境がないので、はずしているかもしれませんが・・

問題は%d無しの時刻部分がないlog4jのログで起きているのですよね?
時刻がないとsyslogが自サーバの時刻を設定するのでやはりsyslogの方の問題かもしれませんね。
ただ途中に中継が入ると、時刻が無い場合そこで補ったりするようなので厄介ですが・・

評価

0

>mioさん、tamaさん
ご回答ありがとうございます。非常に参考になります。tamaさんの回答どおりConversionPatternの時刻部分を%d{MMM dd HH:mm:ss} %-5p以降同じで明日
(今日かな?)やってみます。


>問題は%d無しの時刻部分がないlog4jのログで起き>ているのですよね?
そうです。unix上の以下のコマンドで
「logging local2 ERROR repeate test」
を2回たたいた場合2(2回目の出力は前回同じメッセージの30秒後)
した場合は、
Nov  9 11:56:39 usrA ccc: repeate test  
Nov  9 11:57:09 usrA last message repeated 1 times
となります。
syslogの方の問題が濃厚になってきたので
明日、syslogdのソースも見てみたいと思います。

質問から6ヶ月以上経過しているので、回答を書き込むことはできません。