Skip to content

Log4j2 throws UnsupportedOperationException #97

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
BenjaminTanguay opened this issue Jan 11, 2024 · 10 comments · Fixed by #98
Closed

Log4j2 throws UnsupportedOperationException #97

BenjaminTanguay opened this issue Jan 11, 2024 · 10 comments · Fixed by #98
Milestone
1.2.1

Comments

@BenjaminTanguay
Copy link

BenjaminTanguay commented Jan 11, 2024 •
edited
Loading

Background info:
Vertx 4.5.1
slf4j 2.0.9
log4j 2.21.0
reactiverse-contextual-logging 1.1.2

Problem:
When logging to the console, the following stacktrace is produced:

2024-01-11T12:59:34,943 INFO  HttpOutLogHandler - [vert.x-eventloop-thread-1] - [exchangeId:66a74e3b-40eb-4ac8-80f5-4ae27ec3a9f9, port:20001, uri:/v1/management/version, client:0:0:0:0:0:0:0:1]
  HTTP response code=200
WARN StatusConsoleListener org.apache.logging.slf4j.Log4jEventBuilder caught java.lang.UnsupportedOperationException logging ReusableParameterizedMessage: HTTP response code=200
 java.lang.UnsupportedOperationException
        at java.base/java.util.Collections$UnmodifiableMap.clear(Collections.java:1668)
        at org.apache.logging.log4j.core.impl.JdkMapAdapterStringMap.clear(JdkMapAdapterStringMap.java:123)
        at org.apache.logging.log4j.core.impl.MutableLogEvent.clear(MutableLogEvent.java:144)
        at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.release(ReusableLogEventFactory.java:130)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:559)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:81)
        at org.apache.logging.log4j.core.Logger.log(Logger.java:163)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2066)
        at org.apache.logging.log4j.internal.DefaultLogBuilder.logMessage(DefaultLogBuilder.java:250)
        at org.apache.logging.log4j.internal.DefaultLogBuilder.log(DefaultLogBuilder.java:144)
       ...

After analysis, I've found that the problem seems to be related to this library. More specifically, the class io.reactiverse.contextual.logging.VertxContextDataProvider creates an immutable map that the logging framework later attempts to clear, causing the problem. This stacktrace is repeated for every line that is subsequently logged to the console. I tried creating my own instance of the VertxContextDataProvider with a regular HashMap instead of an immutable collection and the problem seems to be resolved. My problem is that I don't know whether I'm introducing side-effects by changing the data structure accessibility.

Here is the log4j xml file configuration used to produce the problem:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration
        status="warn"
        strict="true"
        name="some-name">
    <Properties>
        <Property name="ServiceSpace" value="some-space"/>
        <Property name="ServiceName" value="some-name"/>
        <Property name="ExecutionEnvironment" value="${env:EXECUTION_ENVIRONMENT}"/>
        <Property name="Layout" value="%style{%d{ISO8601}}{black} %highlight{%-5level} %style{%C{1}}{bright,yellow} - [%t]%notEmpty{ - [exchangeId:%X{exchangeId}, port:%X{port}, uri:%X{uri}, client:%X{clientAddress}]}%n  %style{%msg}{bright}%n%throwable"/>
        <Property name="FileLayout" value="%d{ISO8601} %-5level %C{1} - [%t]%notEmpty{ - [exchangeId:%X{exchangeId}, port:%X{port}, uri:%X{uri}, client:%X{clientAddress}]}%n  %msg%n%throwable"/>
    </Properties>
    <Filter type="ThresholdFilter" level="trace"/>

    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="${Layout}"/>
        </Console>

        <RollingFile name="RollingFile"
                     fileName="./logs/${ServiceName}.log"
                     filePattern="./logs/$${date:yyyy-MM}/${ServiceName}-%d{yyyy-MM-dd}-%i.log.gz">
            <PatternLayout pattern="${FileLayout}"/>
            <Policies>
                <!-- rollover on startup, daily and when the file reaches
                    10 MegaBytes -->
                <OnStartupTriggeringPolicy />
                <SizeBasedTriggeringPolicy
                        size="10 MB" />
                <TimeBasedTriggeringPolicy />
            </Policies>
        </RollingFile>
        
        <RollingFile name="RollingFileJson"
                     fileName="./logs/${ServiceName}-json.log"
                     filePattern="./logs/$${date:yyyy-MM}/${ServiceName}-%d{yyyy-MM-dd}-%i-json.log.gz">
            <JsonTemplateLayout
                    eventTemplateUri="classpath:mcmopiadapter-json-layout.json"
                    stackTraceEnabled="true"
                    locationInfoEnabled="false"
            >
                <EventTemplateAdditionalField key="service-space" value="${ServiceSpace}"/>
                <EventTemplateAdditionalField key="service-name" value="${ServiceName}"/>
                <EventTemplateAdditionalField key="service-environment" value="${ExecutionEnvironment}"/>
            </JsonTemplateLayout>

            <Policies>
                <!-- rollover daily and when the file reaches 10 MegaBytes -->
                <SizeBasedTriggeringPolicy size="10 MB"/>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
    </Appenders>

    <Loggers>
        <Logger name="io.micrometer" level="INFO"/>
        <Logger name="io.netty" level="INFO"/>
        <!-- LOG everything at INFO level unless overriden with -DlogLevel=... -->
        <Root level="${env:LOG_LEVEL:-INFO}">
            <AppenderRef ref="Console" />
            <AppenderRef ref="RollingFile" />
            <AppenderRef ref="RollingFileJson"/>
        </Root>

    </Loggers>

</Configuration>
@tsegismont tsegismont changed the title Bug found when logging to the console using vertx, slf4j, log4j and this library Log4j throws UnsupportedOperationException Jan 12, 2024
@tsegismont tsegismont changed the title Log4j throws UnsupportedOperationException Log4j2 throws UnsupportedOperationException Jan 12, 2024
tsegismont added a commit to tsegismont/reactiverse-contextual-logging that referenced this issue Jan 12, 2024
@tsegismont
UOE may be thrown when using log4j2 with context data provider
77e7a3e 
Fixes reactiverse#97

VertxContextDataProvider relied on the default implementation of ContextDataProvider.supplyStringMap which expects supplyContextData to return a mutable map.

But VertxContextDataProvider returns an immutable map and this is why sometimes (depending on log4j2 config) an UOE can be thrown.

In this commit, VertxContextDataProvider now returns a custom implementation of StringMap. This implementation is "frozen", which means log4j2 will not attempt to modify it.

Because log4j2 expects the StringMap entries to be processed in order, the ContextualDataImpl.getAll implementation has been modified to return a map sorted on its keys.
The map is not typed with SortedMap to reduce the number of methods to implement.
@tsegismont tsegismont mentioned this issue Jan 12, 2024
Merged
@tsegismont
Copy link
Contributor

@BenjaminTanguay I've sent PR #98 which should solve the issue. Can you give it a try?

@tsegismont
Copy link
Contributor

@BenjaminTanguay I'm asking because I wasn't able to reproduce locally

@BenjaminTanguay
Copy link
Author

I'll check...

@BenjaminTanguay
Copy link
Author

@tsegismont The fix seems to work. Thank you for the help!

@blukhand
Copy link

same problem, thank u guys

@tsegismont
Copy link
Contributor

I am concerned that I wasn't able to reproduce. I can see how the previous implementation did not conform to log4j2 expectations, but I would prefer to have a test to add to this PR.

Is any of you able to provide a simple reproducer ?

@BenjaminTanguay
Copy link
Author

I am not familiar with your library and environment so building a test for it may be stretching it. I'll try to create a small sample project to reproduce the problem and you can derive a test from that.

@BenjaminTanguay
Copy link
Author

I tried all day creating a small reproducer based on our production code and I still can't do it. I tried a bunch of permutations but I can't isolate the factor responsible for triggering the bug. I can't justify working on this for much longer so I'll just stop. I may or may not come back to this on my own time.

@tsegismont
Copy link
Contributor

Thanks for trying @BenjaminTanguay . I'll go ahead and merge this.

tsegismont added a commit to tsegismont/reactiverse-contextual-logging that referenced this issue Jan 18, 2024
@tsegismont
UOE may be thrown when using log4j2 with context data provider
0111814 
Fixes reactiverse#97

VertxContextDataProvider relied on the default implementation of ContextDataProvider.supplyStringMap which expects supplyContextData to return a mutable map.

But VertxContextDataProvider returns an immutable map and this is why sometimes (depending on log4j2 config) an UOE can be thrown.

In this commit, VertxContextDataProvider now returns a custom implementation of StringMap. This implementation is "frozen", which means log4j2 will not attempt to modify it.

Because log4j2 expects the StringMap entries to be processed in order, the ContextualDataImpl.getAll implementation has been modified to return a map sorted on its keys.
The map is not typed with SortedMap to reduce the number of methods to implement.
@tsegismont tsegismont added this to the 1.2.0 milestone Jan 18, 2024
tsegismont added a commit that referenced this issue Jan 18, 2024
@tsegismont
UOE may be thrown when using log4j2 with context data provider (#98)
d1e8fe6 
* UOE may be thrown when using log4j2 with context data provider

Fixes #97

VertxContextDataProvider relied on the default implementation of ContextDataProvider.supplyStringMap which expects supplyContextData to return a mutable map.

But VertxContextDataProvider returns an immutable map and this is why sometimes (depending on log4j2 config) an UOE can be thrown.

In this commit, VertxContextDataProvider now returns a custom implementation of StringMap. This implementation is "frozen", which means log4j2 will not attempt to modify it.

Because log4j2 expects the StringMap entries to be processed in order, the ContextualDataImpl.getAll implementation has been modified to return a map sorted on its keys.
The map is not typed with SortedMap to reduce the number of methods to implement.

* Simplify implementation

Safer since we can't reproduce the original bug
@tsegismont tsegismont modified the milestones: 1.2.0, 1.2.1 Jan 18, 2024
@tsegismont
Copy link
Contributor

Fixed in version 1.2.1 (on its way to Maven Central)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
1.2.1
3 participants
@tsegismont @blukhand @BenjaminTanguay