You are viewing a plain text version of this content. The canonical link for it is here.

Posted to dev@logging.apache.org by Gary Gregory <ga...@gmail.com> on 2022/07/21 20:53:34 UTC

Nasty surprise in 2.18.0

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

Posted by Ralph Goers <ra...@dslextreme.com>.


> On Sep 12, 2022, at 11:58 PM, Piotr P. Karwasz <pi...@gmail.com> wrote:
> 
> On Tue, 13 Sept 2022 at 02:24, Ralph Goers <ra...@dslextreme.com> wrote:
>> 1. SLF4J2 support to make the Junit dependency test scope.
> 
> I fixed it yesterday, but if someone else can do a `mvn
> dependency:list -DincludeScope=runtime` and look for dependencies that
> should not be there, it would be better.
> 
>> 2. Fix GelfLayoutTest on Windows.
> 
> It disappeared on my Windows box after increasing the
> `EncodingListAppender` buffer size to 16 KiB. I committed the fix.


This may explain why it didn’t fail when I ran the build in my Windows 10 VM.

Ralph

Re: Nasty surprise in 2.18.0

Posted by "Piotr P. Karwasz" <pi...@gmail.com>.

On Tue, 13 Sept 2022 at 02:24, Ralph Goers <ra...@dslextreme.com> wrote:
> 1. SLF4J2 support to make the Junit dependency test scope.

I fixed it yesterday, but if someone else can do a `mvn
dependency:list -DincludeScope=runtime` and look for dependencies that
should not be there, it would be better.

> 2. Fix GelfLayoutTest on Windows.

It disappeared on my Windows box after increasing the
`EncodingListAppender` buffer size to 16 KiB. I committed the fix.

Piotr

Re: Nasty surprise in 2.18.0

Posted by Ralph Goers <ra...@dslextreme.com>.

Unfortunately, I cancelled the vote for that. I need fixes for
1. SLF4J2 support to make the Junit dependency test scope.
2. Fix GelfLayoutTest on Windows.

If someone can let me know when these are fixed I will create a new release candidate.

Ralph

> On Sep 12, 2022, at 5:01 PM, Gary Gregory <ga...@gmail.com> wrote:
> 
> Hi Piotr,
> 
> I see in the release notes that the fix made it in 2.19.0 RC1, thank you!
> 
> Gary
> 
> On Thu, Jul 21, 2022, 17:33 Gary Gregory <ga...@gmail.com> wrote:
> 
>> Hi Piotr,
>> 
>> Thank you so much for the quick analysis!
>> 
>> Gary
>> 
>> 
>> On Thu, Jul 21, 2022, 17:35 Piotr P. Karwasz <pi...@gmail.com>
>> 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
>>> 
>>

Re: Nasty surprise in 2.18.0

Posted by Gary Gregory <ga...@gmail.com>.

Hi Piotr,

I see in the release notes that the fix made it in 2.19.0 RC1, thank you!

Gary

On Thu, Jul 21, 2022, 17:33 Gary Gregory <ga...@gmail.com> wrote:

> Hi Piotr,
>
> Thank you so much for the quick analysis!
>
> Gary
>
>
> On Thu, Jul 21, 2022, 17:35 Piotr P. Karwasz <pi...@gmail.com>
> 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
>>
>

Re: Nasty surprise in 2.18.0

Posted by Gary Gregory <ga...@gmail.com>.

Hi Piotr,

Thank you so much for the quick analysis!

Gary


On Thu, Jul 21, 2022, 17:35 Piotr P. Karwasz <pi...@gmail.com>
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
>

Re: Nasty surprise in 2.18.0

Posted by "Piotr P. Karwasz" <pi...@gmail.com>.

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