Nasty surprise in 2.18.0

[Gary Gregory]

Hi All,

I just got an unfortunate surprise after updating to 2.18.0. A user
reported that our app broke this like (edited to hide some stuff):

2022-07-21 09:08:31,010 main ERROR Could not create plugin of type
class org.apache.logging.log4j.core.appender.ConsoleAppender for
element Console: java.nio.charset.IllegalCharsetNameException:
-Dlog4j2.configurationFile="C:\ProgramData\path\to\my\config\file.xml"
-Da.custom.property.appender=rolling_file_size
-Da.cusomt.property.logdir="C:\some\special\log"
java.nio.charset.IllegalCharsetNameException:
-Dlog4j2.configurationFile="C:\ProgramData\path\to\my\config\file.xml"
-Da.cusomt.property.appender=rolling_file_size
-Da.cusomt.property.logdir="C:\some\special\log"
   at java.nio.charset.Charset.checkName(Unknown Source)
   at java.nio.charset.Charset.lookup2(Unknown Source)
   at java.nio.charset.Charset.lookup(Unknown Source)
   at java.nio.charset.Charset.isSupported(Unknown Source)
   at 
org.apache.logging.log4j.util.PropertiesUtil.getCharsetProperty(PropertiesUtil.java:215)
   at 
org.apache.logging.log4j.core.appender.ConsoleAppender$Target.getCharset(ConsoleAppender.java:94)
   at 
org.apache.logging.log4j.core.appender.ConsoleAppender$Target$1.getDefaultCharset(ConsoleAppender.java:78)
   at 
org.apache.logging.log4j.core.appender.ConsoleAppender$Builder.build(ConsoleAppender.java:231)
   at 
org.apache.logging.log4j.core.appender.ConsoleAppender$Builder.build(ConsoleAppender.java:195)
   at 
org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:124)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1133)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1058)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:1050)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:659)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:257)
   at 
org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:303)
   at 
org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:621)
   at 
org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:694)
   at 
org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:711)
   at 
org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:253)
   at 
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:155)
   at 
org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
   at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196)
   at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:599)

This happens because the system property "sun.stdout.encoding" has the
value "-Dlog4j2.configurationFile="C:\ProgramData\path\to\my\config\file.xml"
-Da.custom.property.appender=rolling_file_size
-Da.cusomt.property.logdir="C:\some\special\log""

How does this string end up in the system property sun.stdout.encoding?

The script that starts our app uses an environment variable called
LOG4J and starting with 2.18.0, Log4j puts the content of this
environment variable in ALL system properties.

Thoughts?

Gary

Re: Nasty surprise in 2.18.0

[Piotr P. Karwasz]

Hi Gary,

> The script that starts our app uses an environment variable called
> LOG4J and starting with 2.18.0, Log4j puts the content of this
> environment variable in ALL system properties.
>
> Thoughts?

Sorry, I must have broken it while fixing LOG4J-3413. The
ConsoleAppender is actually calling
PropertiesUtil.getCharsetProperty("sun.stdout.encoding") and:

* it looks up a literal environment/system property
"sun.stdout.encoding" and finds nothing,
* it tokenizes "sun.stdout.encoding" and obtains an empty list of
tokens (this should prevent "configurationFile" to be confused with
"log4j2.configurationFile"),
* it normalizes the empty list of tokens and looks up a Java system
property named "log4j2" and an environment variable named "LOG4J".

I'll fix it tomorrow and add a test.

Piotr

Re: Nasty surprise in 2.18.0

[Gary Gregory]

Hi Piotr,

Thank you so much for the quick analysis!

Gary


On Thu, Jul 21, 2022, 17:35 Piotr P. Karwasz 
wrote:

> Hi Gary,
>
> > The script that starts our app uses an environment variable called
> > LOG4J and starting with 2.18.0, Log4j puts the content of this
> > environment variable in ALL system properties.
> >
> > Thoughts?
>
> Sorry, I must have broken it while fixing LOG4J-3413. The
> ConsoleAppender is actually calling
> PropertiesUtil.getCharsetProperty("sun.stdout.encoding") and:
>
> * it looks up a literal environment/system property
> "sun.stdout.encoding" and finds nothing,
> * it tokenizes "sun.stdout.encoding" and obtains an empty list of
> tokens (this should prevent "configurationFile" to be confused with
> "log4j2.configurationFile"),
> * it normalizes the empty list of tokens and looks up a Java system
> property named "log4j2" and an environment variable named "LOG4J".
>
> I'll fix it tomorrow and add a test.
>
> Piotr
>