logging - xwiki logrule がログステートメントをキャプチャしない

Question

ロガー出力をキャプチャするために XWiki LogRule を使用しようとしています。出力がキャプチャされていません。私が間違っていることは明らかではありません。関連するコードとドキュメントを読みましたが、徹底的な検索を行ったと感じていますが、すべて役に立ちませんでした。このソリューションを選択したのは、目前の問題に対して最もエレガントに見えるためです。

問題の範囲と、Mockito 1.8.5 から 1.9.5 への移行に起因する問題の解決策を特定しようとしています。@InjectMocks を使用すると、以前は final フィールドに挿入できましたが、できなくなりました。その理由は理解できます。

解決策の 1 つは、最終修飾子を削除することです。もう 1 つは、オーバーロードされたコンストラクターを作成し、手動で注入することです。最初はまずいです。2 つ目は、テストのみに使用されるコードが導入されているため見苦しく、ロガーをモックする場合、最終的なフィールドはロガーだけです。したがって、ロガーが唯一の問題である場合は、xwiki-commons-test-simple-5.4.1.jar で利用可能な XWiki LogRule を使用するのが理にかなっていると思いました。

テストクラスでのルールの実装は次のとおりです。

@Rule
public LogRule logRule = new LogRule()
{
    {
        record(LogLevel.INFO);
        recordLoggingForType(EmployerNameCacheLoadServiceImpl.class);
    }
};

テストでのルールの実行は次のとおりです。

@Test
public void testLoadCache_FormatAndLogData()
{
    String key = "key";
    String incorrectKey = key + " \n random malicious text";
    String incorrectStorageId = STORAGE_ID + " \n random malicious text";
    String incorrectUserGuid = USER_GUID + " \n random malicious text";
    when(serviceUser.getOwningFirm()).thenReturn(incorrectStorageId);
    when(serviceUser.getUserGuid()).thenReturn(incorrectUserGuid);
    when(employerNameLoadSummaryCache.get(anyString())).thenReturn(null);
    when(searchableEmployerNameFactory.createSearchableEmployerNames(eq(serviceUser), anyString()))
        .thenReturn(new HashMap<String, SearchableEmployerName>());
    when(stringSecurityFormatter.formatString(incorrectKey)).thenReturn(key);
    when(stringSecurityFormatter.formatString(incorrectStorageId)).thenReturn(STORAGE_ID);
    when(stringSecurityFormatter.formatString(incorrectUserGuid)).thenReturn(USER_GUID);

    employerNameCacheLoadService.loadCache(serviceUser, incorrectKey);

    verify(stringSecurityFormatter).formatString(incorrectKey);
    verify(stringSecurityFormatter).formatString(incorrectStorageId);
    verify(stringSecurityFormatter).formatString(incorrectUserGuid);

    String expectedLogEntry =
        String.format("Cache load(%s) of firm (%s) for batch (%s) by user(%s). A total of %d entries.",
                      key,
                      STORAGE_ID,
                      anyString(),
                      USER_GUID,
                      0);

// verify(logger).info(expectedLogEntry); System.out.println("this.logRule.size() is " + this.logRule.size()); System.out.println("this.logRule.toString() is " + this.logRule.toString()); assertThat(this.logRule.size(), is(1)); assertThat(this.logRule.getMessage(0), containsString(expectedLogEntry)); assertThat(this.logRule.toString(), containsString(expectedLogEntry)); }

さまざまなバリエーションを試したことがわかります。logRule.size() の呼び出しは 0 を返し、常に INFO エントリを記録する必要があります。

ターゲットクラスのロガーの定義は次のとおりです。

private final Logger logger = Logger.getLogger(EmployerNameCacheLoadServiceImpl.class);

テスト中のメソッドは次のとおりです。

@Override
public String loadCache(final serviceUser user, final String key)
{
    NamesLoadSummary namesLoadSummary = employerNameLoadSummaryCache.get(key);

    String batchId = null;
    Date now = new Date();
    if (namesLoadSummary == null || now.after(namesLoadSummary.getExpiresDateTime()))
    {
        batchId = UUID.randomUUID().toString().replace("-", "");
        final Map<String, SearchableEmployerName> mapOfSearchableNames =
            searchableEmployerNameFactory.createSearchableEmployerNames(user, batchId);

        employerNamesCache.putAll(mapOfSearchableNames);

        namesLoadSummary = new NamesLoadSummary();
        namesLoadSummary.setBatchId(batchId);
        namesLoadSummary.setStorageId(key);
        namesLoadSummary.setExpiresDateTime(employerNameCacheExpiryCalculator.calculateExpiryDate());

        employerNameLoadSummaryCache.put(key, namesLoadSummary);

        logger.info(String.format("Cache load(%s) of firm (%s) for batch (%s) by user(%s). A total of %d entries.",
                                  stringSecurityFormatter.formatString(key),
                                  stringSecurityFormatter.formatString(user.getOwningFirm()),
                                  batchId,
                                  stringSecurityFormatter.formatString(user.getUserGuid()),
                                  mapOfSearchableNames.size()));
    }
    else
    {
        batchId = namesLoadSummary.getBatchId();
    }
    return batchId;
}

コンソール出力は次のとおりです。

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/c164033/tools/jars/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Users/c164033/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
14:41:00,556 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
14:41:00,557 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-test.xml] at [file:/C:/Users/c164033/workspace/Contacts/bin/logback-test.xml]
14:41:00,558 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-test.xml] occurs multiple times on the classpath.
14:41:00,558 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-test.xml] occurs at [jar:file:/C:/Users/c164033/tools/jars/xwiki-commons-test-simple-5.4.1.jar!/logback-test.xml]
14:41:00,558 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-test.xml] occurs at [file:/C:/Users/c164033/workspace/Contacts/bin/logback-test.xml]
14:41:00,621 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
14:41:00,669 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
14:41:00,681 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
14:41:00,707 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
14:41:00,783 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - com.xxx.yyy.zzz level set to INFO
14:41:00,783 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - org.hibernate level set to ERROR
14:41:00,783 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
14:41:00,783 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
14:41:00,783 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
14:41:00,784 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1a7553 - Registering current configuration as safe fallback point

SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
2014-03-21 14:41:01,037 INFO  [main] EmployerNameCacheLoadServiceImpl: Cache load(key) of firm (storageId) for batch (ded2a5d7c9124fa0b3269afe355001e0) by user(userGuid). A total of 0 entries.
this.logRule.size() is 0
this.logRule.toString() is com.xxx.yyy.zzz.contacts.employer.name.EmployerNameCacheLoadServiceImplTests$1@9fa7ba

ご覧のとおり、実際にログに記録されます。また、いくつかの slf4j バインディングの警告があることもわかります。それらが問題であるようには見えませんが、これが投稿され次第、その角度をさらに調査する予定です.

私が求めているのは、LogRule がログに記録された出力をキャプチャするように、この問題を解決するための提案です。

最初の投稿の後、 logback-test.xml をプロジェクトに追加できなかったことに気付きました。そうすることで、テストは以前と同じように失敗しますが、コンソールは異なります。上記のコンソールログには、その変更が反映されています。

ここに私のlog4j.xmlがあります：

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
    <appender name="ConsoleAppender" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%t] %c{1}: %m%n"/>
        </layout>
    </appender>

    <logger name="com.xxx.yyy.zzz">
        <level value="INFO" />
    </logger>

    <logger name="org.hibernate">
        <level value="ERROR" />
    </logger>

    <root>
        <level value="WARN"/>
        <appender-ref ref="ConsoleAppender"/>
    </root>
</log4j:configuration>

そして、前述の logback-test.xml は次のとおりです。

<?xml version="1.0" encoding="UTF-8"?>

<!--
 * See the NOTICE file distributed with this work for additional
 * information regarding copyright ownership.
 *
 * This is free software; you can redistribute it and/or modify it
 * under the terms of the GNU Lesser General Public License as
 * published by the Free Software Foundation; either version 2.1 of
 * the License, or (at your option) any later version.
 *
 * This software is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
 * Lesser General Public License for more details.
 *
 * You should have received a copy of the GNU Lesser General Public
 * License along with this software; if not, write to the Free
 * Software Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA
 * 02110-1301 USA, or see the FSF site: http://www.fsf.org.
-->

<!-- Logback Test configuration that only logs at error level -->
<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <!-- It's important that we log with the same default values as the ones used at runtime, so that tests see what
       is really printed at runtime. Thus tests should capture their output to not print anything in the console
       and assert what's printed using the LogRule class. -->

    <logger name="com.xxx.yyy.zzz">
        <level value="INFO" />
    </logger>

    <logger name="org.hibernate">
        <level value="ERROR" />
    </logger>

  <root level="warn">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

logging - xwiki logrule がログ ステートメントをキャプチャしない

1 に答える 1

Related

Reference

logging - xwiki logrule がログステートメントをキャプチャしない