log4j2 how to disable "date:" lookup - log4j throws exception

Question

edit seems not to be possible at the moment filed an issue.

---

i am using log4j2 in my apache camel application. In camel file names can be configured this way "?fileName=${date:now:yyyyMMdd-HHmmss}ID.${id}.gz"

if i set log level to debug camel tries to log what it is doing but log4j seems to try to lookup/interpret the string with "date:" and throws an exception:

2014-11-24 11:29:19,218 ERROR Invalid date format: "now:yyyyMMdd-HHmmss", using default java.lang.IllegalArgumentExcepti
on: Illegal pattern character 'n'
        at java.text.SimpleDateFormat.compile(Unknown Source)
        at java.text.SimpleDateFormat.initialize(Unknown Source)
        at java.text.SimpleDateFormat.<init>(Unknown Source)
        at java.text.SimpleDateFormat.<init>(Unknown Source)
        at org.apache.logging.log4j.core.lookup.DateLookup.formatDate(DateLookup.java:60)
        at org.apache.logging.log4j.core.lookup.DateLookup.lookup(DateLookup.java:53)
        at org.apache.logging.log4j.core.lookup.Interpolator.lookup(Interpolator.java:144)
        at org.apache.logging.log4j.core.lookup.StrSubstitutor.resolveVariable(StrSubstitutor.java:1008)
        at org.apache.logging.log4j.core.lookup.StrSubstitutor.substitute(StrSubstitutor.java:926)
        at org.apache.logging.log4j.core.lookup.StrSubstitutor.substitute(StrSubstitutor.java:816)
        at org.apache.logging.log4j.core.lookup.StrSubstitutor.replace(StrSubstitutor.java:385)
        at org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatternConverter.java:71)
        at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
        at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:189)
        at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:53)
        at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:52)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:
104)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:428)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
        at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1347)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1312)
        at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:132)
        at org.apache.camel.util.IntrospectionSupport.setProperty(IntrospectionSupport.java:518)
        at org.apache.camel.util.IntrospectionSupport.setProperty(IntrospectionSupport.java:570)
        at org.apache.camel.util.IntrospectionSupport.setProperties(IntrospectionSupport.java:454)
        at org.apache.camel.util.EndpointHelper.setProperties(EndpointHelper.java:249)
        at org.apache.camel.impl.DefaultComponent.setProperties(DefaultComponent.java:272)
        at org.apache.camel.component.file.GenericFileComponent.createEndpoint(GenericFileComponent.java:67)
        at org.apache.camel.component.file.GenericFileComponent.createEndpoint(GenericFileComponent.java:37)
        at org.apache.camel.impl.DefaultComponent.createEndpoint(DefaultComponent.java:123)
        at org.apache.camel.impl.DefaultCamelContext.getEndpoint(DefaultCamelContext.java:514)
        at org.apache.camel.impl.DefaultCamelContext.getEndpoint(DefaultCamelContext.java:547)

Is there a way to turn off this "date:" lookup? Why does it try to interpret stuff coming from log at all? I think it should not be touched in any way?!

Edit, very easy to reproduce in test:

public class LogTest {

    private Logger log = LoggerFactory.getLogger(LogTest.class);

    @Test
    public void test() {
        log.info("${date:now:buhu}");

    }
}

It is crucial to us ${date:} - only "data:now" is working. So this problem is completely independent from camel, but camel uses ${date:...} pattern for several things. Here is a simple route that reproduces the problem - the exception will be thrown on camel set up phase - no test code needed - logging level must be "debug"!:

public class LogTest extends CamelTestSupport{

    private Logger log = LoggerFactory.getLogger(LogTest.class);

    @Test
    public void test() {
        //log.info("${date:now:yyyyMMdd-HHmmss}");

    }

    @Override
    protected RouteBuilder createRouteBuilder() throws Exception {
        return new RouteBuilder() {

            @Override
            public void configure() throws Exception {
                from("direct:a").to("file:./?fileName=${date:now:yyyyMMdd-HHmmss}ID.${id}.gz");
            }
        };
    }

}

Chimene

Can you show us the complete route pls? – Tubb

added route, but as i stated the problem is reproducible without camel. – Chimene

You're mixing up camel syntax and log4j syntax: * camel file component: date:now * log4j: example date:yyyy-MM-dd So log.info("${date:now:yyyyMMdd-HHmmss}"); won't work with the used syntax, remove the :now there. – Tubb

no no "${date:now:yyyyMMdd-HHmmss}" this is normal and allowed camel syntax. see here camel.apache.org/simple.html (find "date:now:"). and on debug level camel just tries to log it. – Chimene

Yes, but this line can't work log.info("${date:now:yyyyMMdd-HHmmss}"); – Tubb

this line is commented out and is only to reproduce the problem - it shows the problem is independent to camel. On the other hand it should be possible to log all i want - there should be no limitations, allowed/disallowed strings! Many applications use slf4j/decouple from logging implementation - but this problem is log4j2 specific i think - big problem?! – Chimene

I'm not sure your assumption that this issue is independent from camel is correct. Maybe there is a conflict between the camel file component and log4j2. – Tubb

they are independent projects. and there is no documented restriction (please show if i am wrong) that it is not allowed to log log.info("${date:now:yyyyMMdd-HHmmss}"); <- and this isn't working independently of camel. – Chimene

I am getting this error on my project as well. It's annoying but not critical for us. I think this may require an update on the Camel side to make sure any output they try logging (in this instance, their custom "now:" syntax) is parseable by SimpleDateFormat – Fears

Never mind, I see how this is a log4j2 issue now. – Fears

Please raise this issue on the log4j2 Jira issue tracker. – Pavid

But why do you want to log the ${} pattern anyway (and not the actual time)? – Highlander

please read - there are libraries that use ${} syntax and those libraries do log such stuff. one example apache camel – Chimene

CVE-2021-44228 – Xiphisternum

Yup, this turned out to be a much bigger issue, one of the few early warning signs of Log4Shell. Added new answer. – Wherewith

Answer 1

This issue was fixed in 2.7 version of Log4j2.

The solution is to upgrade to that version (or higher) and add in the pattern attribute the option "{nolookups}" to %msg .

%msg{nolookups}

For example

<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %class{1} %L %M %t - %msg{nolookups}%n%xEx%n" />

Sapiential

Answer 2

The problem can be avoided, if the simple-Expression is written as $simple{..} instead of ${..}. Then log4j2 won't use his Date-Lookup.

So, if you change your Route from:

from("direct:a").to("file:./?fileName=${date:now:yyyyMMdd-HHmmss}ID.${id}.gz"); 

to:

from("direct:a").to("file:./?fileName=$simple{date:now:yyyyMMdd-HHmmss}ID.${id}.gz");

it should work, even if you debug Camel.

Aeon

Answer 3

The correct solution is now to upgrade the log4j-core library to 2.15.0 or above. At time of writing, the latest and current recommended version is 2.16.0.

The variable substitutions happening in logged messages here are symptoms of the same feature exploited in CVE-2021-44228, aka Log4Shell.

The feature is disabled by default in 2.15.0 and removed in 2.16.0.

It's not news to anyone by now, but it's really important to take steps to disable this feature, as a security measure, even if not using Apache Camel or encountering the issue as described.

As an aside, I found this question when searching for early warning signs of the Log4Shell vulnerability. I've quoted it in my write-up.

Wherewith

Answer 4

To disable the date lookup locally, you can add a "$" in front of the expression:

    log.info("$${date:now:buhu}");

This will print ${date:now:buhu} instead of throwing an exception printing the stack trace.

As for how to avoid this using Camel, I'm not sure. The cleanest fix would probably be a log4j2 update to disable their DateLookup feature. A temporary fix is to disable DEBUG level logs from the org.apache.camel package:

 <loggers>
     <logger name="org.apache.camel" level="INFO" />
     <root level="debug">
        <appender-ref ref="Console" />
     </root>
 </loggers>

It's not ideal, but we can increase the log level if we ever need to debug Camel context creation since the log statements are not necessary for general everyday development.

Fears

thanks for the info, should i file a bug/feature? or is there already a ticket regarding this problem? I think their should be a switch to completely disable lookup or all log output manipulating stuff?! – Chimene