I am trying to use the XWiki LogRule to capture logger output. No output is being captured. It is not clear what I am doing wrong. I have read the associated code and documents, and feel I have done a thorough search - all to no avail. I have chosen this solution for it seems the most elegant for the problem at hand.
I am trying to determine the scope of the problems and possible solutions to those problems arising from migrating from Mockito 1.8.5 to 1.9.5. We used to be able to insert into final fields and no longer can - and I understand why - using @InjectMocks.
One solution is to remove the final modifier. Another is to create overloaded constructors and inject manually. The first is unpalatable. The second is ugly, as it introduces code that is only used for testing, and when mocking a logger, the logger is the only field that is final. So, in those cases where the logger is the only issue, I thought it would make sense to use the XWiki LogRule available in xwiki-commons-test-simple-5.4.1.jar.
Here is the implementation of the rule in the test class:
@Rule
public LogRule logRule = new LogRule()
{
{
record(LogLevel.INFO);
recordLoggingForType(EmployerNameCacheLoadServiceImpl.class);
}
};
Here is the execution of the rule in the test:
@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)); }
You can see that I have tried a number of variations. The call to logRule.size() returns 0 and it should always log an INFO entry.
Here is the definition of the logger in the target class:
private final Logger logger = Logger.getLogger(EmployerNameCacheLoadServiceImpl.class);
Here is the method under test:
@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;
}
And here is the console output:
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
As you can see, it does actually log. You can see also that there are some slf4j binding warnings. It doesn't seem those should be the problem but will be researching that angle further as soon as this is posted.
What I am seeking is suggestions for resolving this problem so that the LogRule will capture the logged output.
I realized - after my original posting - that I had failed to add the logback-test.xml to my project. Doing so, the test is still failing as before, but the console is different. The console log above now reflects that change.
Here is my 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>
And, here is the aforementioned 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>
