2012-02-21 12 views
5

私はslf4jをログバックで使用しています。時には、ログが順序(タイムスタンプ)で印刷されないことがあります。 コードが実行されているのと同じ順序でログインするように強制できますか?slf4jがログを順番に出力するように強制します。

更新1:これは、Jenkinsのユニットテストをmavenで実行しているときに発生しています。一貫して起こっている。コードからの最初のログ・ステートメントが来て、ユニット・テストからのログ・ステートメントが来ています。

また、すべてのログバックファイルは以下のように正常に表示されます。

<appender name="STDOUT" 
      class="ch.qos.logback.core.ConsoleAppender"> 
    <layout class="ch.qos.logback.classic.PatternLayout"> 

アップデート2:ログ・スニペットは、(私は、ファイル名などを編集している。)このようなものです。テスト1の実行中に、何らかのエラーのために失敗したトランザクションをリバースするコードを呼び出します。 しかし、奇妙なことは、例外が最初に出力された後、テストメソッドのログステートメントが出力されることです。また、期待通りにログステートメントのタイムスタンプがありますが、ファイル内でそれらの順序が異なっている(午前14時33分34秒。は午前14時33分34秒前に来る。)

14:33:34.667 [[email protected]] [] WARN org.hibernate.ejb.Ejb3Configuration - hibernate.connection.autocommit = false break the EJB3 specification 
14:33:34.718 [[email protected]] [] WARN o.h.impl.SessionFactoryObjectFactory - InitialContext did not implement EventContext 
14:33:34.843 [[email protected]] [] DEBUG c.r.a.exception.ExceptionMapper - <3003> can't reverse transaction. [id=10000000100120014] 
. 
. 
. 
. 
. 
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test0: finished. 
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test1: started. 
. 
. 
. 
. 
14:33:34.449 [main] [] DEBUG c.r.a.test - reversing transaction, id=10000000100120014 
14:33:34.856 [main] [] DEBUG c.r.a.test - ========================= test2: started. 

更新3:私たちのプロジェクトはmavenを使用しており、複数のモジュールがあります。 logback-test.xmlsrc/test/resourcesです。

プロジェクト構造はこのようです
codemodule/src/test/resources/logback-test.xml - このモジュールはjarファイルにパッケージされます。テストケースは、このモジュールのコードを呼び出します。
parent/src/test/resources/logback-test.xml - これは他のすべてのモジュールのjarファイルとパッケージをwarにラップする親モジュールです。ここで私はテストケースを実行しており、モジュールのコードの上にそれを呼び出します。

私はテストケースコードと実際のコードの両方でログステートメントを持っています。テストケースとコードの両方が親のログバックファイルのパターンを使用していることを確認しました(コードモジュール内のパターンは異なります)。 テストケースのログを出力する前に、コードのログステートメントを一貫して出力します。

また、テストは並行して実行されていません。
Concurrency config is parallel='none', perCoreThreadCount=true, threadCount=2, useUnlimitedThreads=false

更新4:私は問題を理解しています。私たちは直接メソッド呼び出しではなく、httpリクエストを作成しています。したがって、テストケースはmainスレッドで実行されており、実際のコードは別のスレッドで実行されています(感謝Sebbe)。

私はロギングシーケンスがパフォーマンスヒットすることがあると理解していますが、質問の完全性のためにもう1つ質問します。

両方のログが単一のアペンダー(STDOUT)に送られるため、タイムスタンプの順番でログに記録できますか?

+0

ログには、タイムスタンプが混在したメッセージが表示されます(成長していないことはありますか)。どちらのアペンダーを使っていますか? –

+0

@TomaszNurkiewiczはい、ch.qos.logback.core.ConsoleAppenderを使用しています – Reddy

+0

どの並行処理を使用していますか?それが原因かもしれません。また、ログ抜粋を提供することができます – Fixpoint

答えて

2

ログ自体からは、少なくとも2つのスレッドが実行されていることがわかります。 [email protected]mainです。

別々のスレッドがイベントを同じ出力に記録する順序を制御することはできません(可能性はありますが、悪い考えです)。ログ・スレッド[email protected]から

は、まずあなたのコンソールへの書き込みアクセスを取得します。それに書き込む間、イベントはmainから記録されます。 [email protected]がロックを解除すると、mainがそれを取得し、ログをファイルにフラッシュできます。

+0

Sebbeさん、ありがとうございました。しかし、私はなぜそれが一貫して起こっているのか、 '869082978 @ qtp-1587505558-0'が来るのかを確認する必要があります。 – Reddy

+0

しかし私は問題を持っているが、別の質問があった。更新された(#4)質問。 – Reddy

関連する問題