When the `message` contains a `placeholder({})` but the `arguments` is `0`, an exception will be thrown

[panbingkun]

Description

When the message contains a placeholder({}) but the arguments is 0, an exception will be thrown.

https://github.com/panbingkun/spark/actions/runs/8182167017/job/22373124743
This issue was originally discovered during the compilation process of Spark's GitHub workflow. I am not sure if it is a bug or expected behavior, so I am here to ask for your advice.

Configuration

# This log4j config file is for integration test SparkConfPropagateSuite.
rootLogger.level = debug
rootLogger.appenderRef.stdout.ref = console

appender.console.type = Console
appender.console.name = console
appender.console.target = SYSTEM_ERR
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d{HH:mm:ss.SSS} %p %c: %maxLen{%m}{512}%n%ex{8}%n

Version:
2.23.0, 2.22.0, 2.21.0, 2.19.0 ...
(I have verified several versions, and it seems that this issue exists in all of them.)

Operating system:
Ubuntu 22.04.4 LTS And macos Sonama 14.3.1.

JDK:
JDK 17

Logs

ERROR StatusConsoleListener An exception occurred processing Appender File
 java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `0, VisitedIndex{visitedIndexes={}}: [age] r:0`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:233)
	at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:266)
	at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:120)
	at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:355)
	at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:252)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:238)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2933)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2886)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2868)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2658)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2421)
	at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:128)
	at org.apache.parquet.io.MessageColumnIO$MessageColumnIORecordConsumer.log(MessageColumnIO.java:283)
	at org.apache.parquet.io.MessageColumnIO$MessageColumnIORecordConsumer.printState(MessageColumnIO.java:269)
	at org.apache.parquet.io.MessageColumnIO$MessageColumnIORecordConsumer.startField(MessageColumnIO.java:318)
	at org.apache.parquet.io.RecordConsumerLoggingWrapper.startField(RecordConsumerLoggingWrapper.java:52)

Reproduction

It can be reproduced in the following simple way:

import java.util.BitSet;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class TestLog4j2 {

  private static final Logger LOG = LoggerFactory.getLogger(TestLog4j2.class);

  private static BitSet visitedIndexes = new BitSet();

  public static void main(String[] args) {
    System.out.println(visitedIndexes);
    log(visitedIndexes.toString());
    System.out.println("Done");
  }

  private static void log(Object message, Object...parameters) {
    LOG.error("" + message, parameters);
  }
}

The output is:

{}
ERROR StatusConsoleListener An exception occurred processing Appender File
 java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `{}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:233)
	at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:266)
	at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:120)
	at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:355)
	at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:252)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:238)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2933)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2886)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2868)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2658)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2421)
	at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:308)
	at test.org.apache.parquet.column.page.TestLog4j2.log(TestLog4j2.java:20)
	at test.org.apache.parquet.column.page.TestLog4j2.main(TestLog4j2.java:15)
ERROR StatusConsoleListener An exception occurred processing Appender STDOUT
 java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `{}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:233)
	at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:266)
	at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:120)
	at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:44)
	at org.apache.logging.log4j.core.pattern.MaxLengthConverter.format(MaxLengthConverter.java:88)
	at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:355)
	at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:252)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:238)
	at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2933)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2886)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2868)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2658)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2421)
	at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:308)
	at test.org.apache.parquet.column.page.TestLog4j2.log(TestLog4j2.java:20)
	at test.org.apache.parquet.column.page.TestLog4j2.main(TestLog4j2.java:15)
Done

In addition, if we use the following logic, it seems to be able to bypass it (without throwing an exception)

import java.util.BitSet;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class TestLog4j2 {

  private static final Logger LOG = LoggerFactory.getLogger(TestLog4j2.class);

  private static BitSet visitedIndexes = new BitSet();

  public static void main(String[] args) {
    System.out.println(visitedIndexes);
    log(visitedIndexes.toString());
    System.out.println("Done");
  }

  private static void log(Object message, Object...parameters) {
    if (parameters.length == 0) {
      LOG.error("" + message);
    } else {
      LOG.error("" + message, parameters);
    }
  }
}

The output is:

{}
15:19:18.728 ERROR test.org.apache.parquet.column.page.TestLog4j2: {}

Done

I would like to ask very politely, is it an expected behavior (the caller needs to decide whether to call error(String msg) or call error(String format, Object... arguments) based on whether the length of the arguments is 0, bypassing it), or is it a bug?

[panbingkun]

Sorry to bother you again, friendly cc @vy @ppkarwasz
Thank you very much!

[ppkarwasz]

@panbingkun,

This was fixed in #2343 (throwing an exception is not the correct behavior), which is included in the version 2.23.1 that is currently being voted on.

Can you check the release candidate from this dev@logging thread and vote on it?

[panbingkun]

@panbingkun,

This was fixed in #2343 (throwing an exception is not the correct behavior), which is included in the version 2.23.1 that is currently being voted on.

Can you check the release candidate from this dev@logging thread and vote on it?

@ppkarwasz
Sure, let me check it. Thank you very much!

[vy]

@panbingkun, the fact that Log4j doesn't throw an exception for log("foo {}", new Object[0]), I would say, is a bug. Contrast this with String.format("foo %s"), which will throw an exception. But this behaviour has been there for so long, users treat it as a feature, and I think, this is wrong.

We will release 2.23.1 sometime tomorrow afternoon and there we restored the old behaviour, that is, log("foo {}", new Object[0]) will

1. log foo {} string
2. dump an error to stderr (that is, the low level log of the logging system, Log4j, itself)

Why does log("foo {}") work whereas log("foo {}", new Object[0]) doesn't.

Because, log("foo {}") gets translated to new SimpleMessage("foo {}"), which doesn't perform any placeholder substitution. OTOH, log("foo {}", new Object[0]) gets translated to new ParameterizedMessage("foo {}", new Object[0]), which performs placeholder substitution, and fails as expected.

The recommendation

I strongly advise you to refactor your log() usages such that, use log(String) if you don't expect it to be treated as a parameterized message, or use log(String, Object[]) if you indeed want parameter processing.

Please don't assume that it is still okay to use log("foo {}", new Object[0]), because it will work in 2.23.1. Yes, it will work, but...

1. It will be a way more expensive operation (since an exception is thrown and caught)
2. Your stderr will be polluted

[panbingkun]

@panbingkun,
This was fixed in #2343 (throwing an exception is not the correct behavior), which is included in the version 2.23.1 that is currently being voted on.
Can you check the release candidate from this dev@logging thread and vote on it?

@ppkarwasz Sure, let me check it. Thank you very much!

After verification, the issue still exists, and the information is as follows:

/Users/panbingkun/Developer/spark/jdk/jdk17.0.8/bin/java -javaagent:/Users/panbingkun/Applications/IntelliJ IDEA Community Edition.app/Contents/lib/idea_rt.jar=52254:/Users/panbingkun/Applications/IntelliJ IDEA Community Edition.app/Contents/bin -Dfile.encoding=UTF-8 -classpath /Users/panbingkun/Developer/spark/spark-dependency/log4j2-test/target/classes:/Users/panbingkun/.m2/repository/org/slf4j/slf4j-api/2.0.12/slf4j-api-2.0.12.jar:/Users/panbingkun/.m2/repository/org/slf4j/jul-to-slf4j/2.0.12/jul-to-slf4j-2.0.12.jar:/Users/panbingkun/.m2/repository/org/slf4j/jcl-over-slf4j/2.0.12/jcl-over-slf4j-2.0.12.jar:/Users/panbingkun/.m2/repository/org/apache/logging/log4j/log4j-slf4j2-impl/2.23.1-SNAPSHOT/log4j-slf4j2-impl-2.23.1-SNAPSHOT.jar:/Users/panbingkun/.m2/repository/org/apache/logging/log4j/log4j-api/2.23.1-SNAPSHOT/log4j-api-2.23.1-SNAPSHOT.jar:/Users/panbingkun/.m2/repository/org/apache/logging/log4j/log4j-core/2.23.1-SNAPSHOT/log4j-core-2.23.1-SNAPSHOT.jar:/Users/panbingkun/.m2/repository/org/apache/logging/log4j/log4j-1.2-api/2.23.1-SNAPSHOT/log4j-1.2-api-2.23.1-SNAPSHOT.jar org.apache.spark.log4j2.TestLog4j2


{}
2024-03-07T08:36:34.411420Z main ERROR Unable to format msg: {} java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `{}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)
	at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:282)
	at org.apache.logging.log4j.message.ParameterizedMessage.getFormattedMessage(ParameterizedMessage.java:263)
	at org.apache.logging.log4j.core.async.InternalAsyncUtil.makeMessageImmutable(InternalAsyncUtil.java:41)
	at org.apache.logging.log4j.core.impl.MutableLogEvent.setMessage(MutableLogEvent.java:223)
	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.createEvent(ReusableLogEventFactory.java:99)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:573)
	at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:73)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2906)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2859)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2841)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2631)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2394)
	at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:308)
	at org.apache.spark.log4j2.TestLog4j2.log(TestLog4j2.java:21)
	at org.apache.spark.log4j2.TestLog4j2.main(TestLog4j2.java:16)

16:36:34.412 [main] ERROR org.apache.spark.log4j2.TestLog4j2 - {}
Done

Process finished with exit code 0

[ppkarwasz]

I would also remark that while:

String userData = ...
log.info(userData);

is a safe way to log user generated data,

String userData = ...
Object[] params = ...
log.info(userData, params);

is a security risk similar to SQL injection: users can craft a special format specifier to retrieve some data from params (e.g. an exception).

If you are using Logger#info(String, Object...), the first parameter should be a compile-time constant.

[ppkarwasz]

@panbingkun,

After verification, the issue still exists, and the information is as follows:

{}
2024-03-07T08:36:34.411420Z main ERROR Unable to format msg: {} java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `{}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)
	...

This actually works as designed: if you don't provide enough arguments, you get the format specifier {} in your logs and an error message on the status logger (System.err).

[panbingkun]

@panbingkun, the fact that Log4j doesn't throw an exception for log("foo {}", new Object[0]), I would say, is a bug. Contrast this with String.format("foo %s"), which will throw an exception. But this behaviour has been there for so long, users treat it as a feature, and I think, this is wrong.

We will release 2.23.1 sometime tomorrow afternoon and there we restored the old behaviour, that is, log("foo {}", new Object[0]) will

1. log foo {} string
2. dump an error to stderr (that is, the low level log of the logging system, Log4j, itself)

Why does log("foo {}") work whereas log("foo {}", new Object[0]) doesn't.

Because, log("foo {}") gets translated to new SimpleMessage("foo {}"), which doesn't perform any placeholder substitution. OTOH, log("foo {}", new Object[0]) gets translated to new ParameterizedMessage("foo {}", new Object[0]), which performs placeholder substitution, and fails as expected.

The recommendation

I strongly advise you to refactor your log() usages such that, use log(String) if you don't expect it to be treated as a parameterized message, or use log(String, Object[]) if you indeed want parameter processing.

Please don't assume that it is still okay to use log("foo {}", new Object[0]), because it will work in 2.23.1. Yes, it will work, but...

1. It will be a way more expensive operation (since an exception is thrown and caught)
2. Your stderr will be polluted

@vy log("foo {}", new Object[0]) also seems to have thrown an exception, as follows:

[panbingkun]

@panbingkun,

After verification, the issue still exists, and the information is as follows:

{}
2024-03-07T08:36:34.411420Z main ERROR Unable to format msg: {} java.lang.IllegalArgumentException: found 1 argument placeholders, but provided 0 for pattern `{}`
	at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)
	...

This actually works as designed: if you don't provide enough arguments, you get the format specifier {} in your logs and an error message on the status logger (System.err).

Okay, i see!
It does not throw an exception, but only prints it out, and the following logic still executes.

[panbingkun]

I see.
Also, from my example above, it seems that refactoring the method log is a good choice, because when visitedIndexes(BitSet) is empty, visitedIndexes.toString() result is: {}, In this case, log4j2 considers it to be a parameterized log call, so it printed a similar prompt message to stderr. (Just a prompt, the following code (System.out.println("Done")) will continue to run).
Thank you all.