You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "davemessink (via GitHub)" <gi...@apache.org> on 2023/02/09 20:09:08 UTC

[GitHub] [logging-log4j2] davemessink opened a new issue, #1273: ReusableMessages not getting released when using entry/exit logging

davemessink opened a new issue, #1273:
URL: https://github.com/apache/logging-log4j2/issues/1273

   ## Description
   
   I was getting some `ReusableMessageFactoryTest` failures in the release-2.x branch (without any modifications). It seemed that another test (TraceLoggingTest) was leaving an unreleased `ReusableParameterizedMessage` in the `ReusableMessageFactory` thread local. This only seems to be happening in my new dev environment (Azure VM) and is test order specific.
   
   In the `DefaultFlowMessageFactory#newEntryMessage()`, entry ReusableMessages were being converted to immutable Messages and failing to release the original ReusableMessage.
   
   In contrast, in `DefaultFlowMessageFactory#newExitMessage()`, ReusableMessages were being used directly (without being made immutable). I'm not sure if this was an oversight, but I decided to make both methods call into makeImmutable().
   
   This issue would leave ReusableMessages reuse in a useless state after entry/exit logging was used by a thread.
   
   ## Configuration
   
   **Version:** release-2.x
   **Operating system:** Azure Linux VM
   **JDK:** JDK8
   
   ## Logs
   ```
   [ERROR] Failures:
   [ERROR]   ReusableMessageFactoryTest.testCreateEventOverwritesFields:81->assertReusableParameterizeMessage:58 reserved ==> expected: <true> but was: <false>
   [ERROR]   ReusableMessageFactoryTest.testCreateEventReturnsSameInstance:47 expected: <ReusableParameterizedMessage[messagePattern=null, stringArgs=[1, 2, 3, 4], throwable=null]> but was: <ReusableParameterizedMessage[messagePattern=text, p0={} p1={} p2={} p3={}, stringArgs=[9, 8, 7, 6], throwable=null]>
   [INFO]
   [ERROR] Tests run: 683, Failures: 2, Errors: 0, Skipped: 2
   ```
   
   ## Reproduction
   
   I'm not sure how to influence the order in which Maven runs tests. I added a test to TraceLoggingTest that shows that the thread local Message used is not being released.
   
   ```
       // Ensure that ReusableParameterizedMessages are getting released correctly
       @Test
       public void testReusableMessageHandling() throws InstantiationException, IllegalAccessException {
           assertSame(AbstractLogger.DEFAULT_MESSAGE_FACTORY_CLASS, ReusableMessageFactory.class,
                   "The default message factory has changed");
           
           final MessageFactory factory = new ReusableMessageFactory();
           final Message reusedMessage = factory.newMessage("test {}", null);
           ReusableMessageFactory.release(reusedMessage);
   
           traceEntry("Entry test {}", 0);
           assertReusedMessage(reusedMessage, factory);
   
           traceExit("Exit test {}", 0);
           assertReusedMessage(reusedMessage, factory);
       }
   
       private void assertReusedMessage(Message reusableMessage, MessageFactory factory) {
           final Message testMessage = factory.newMessage("test {}", 0);
   
           assertSame(reusableMessage, testMessage);
   
           ReusableMessageFactory.release(testMessage);
       }
   ```
   


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org


[GitHub] [logging-log4j2] davemessink commented on issue #1273: ReusableMessages not getting released when using entry/exit logging

Posted by "davemessink (via GitHub)" <gi...@apache.org>.
davemessink commented on issue #1273:
URL: https://github.com/apache/logging-log4j2/issues/1273#issuecomment-1425018910

   I'm not sure I'm comfortable moving the release/recycle logic into memento(). Is that the suggestion here? Other uses of memento() are to populate the ring buffer event builder and the MutibleLogEvent. The release() call is currently outside of those blocks (it's currently called by the AbstractLogger in a try/finally block).
   
   I see that a lot of this logic is changing in #1193, what's the suggestion on timing of my PR and that one. Should I wait and address this after that PR is merged? Or get my PR merged quickly?


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org


[GitHub] [logging-log4j2] ppkarwasz commented on issue #1273: ReusableMessages not getting released when using entry/exit logging

Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #1273:
URL: https://github.com/apache/logging-log4j2/issues/1273#issuecomment-1425195231

   My bad, I didn't notice the other use cases of `ReusableMessage#memento()`.
   
   #1194 will not be backported to 2.x, so a PR for 2.x is welcome.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org


[GitHub] [logging-log4j2] ppkarwasz commented on issue #1273: ReusableMessages not getting released when using entry/exit logging

Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #1273:
URL: https://github.com/apache/logging-log4j2/issues/1273#issuecomment-1424826536

   @davemessink, very nice catch! Can you submit a PR to fix it?
   
   I believe that calling `ReusableMessage#memento()` should release the `ReusableMessage`. This needs to be documented in the Javadoc and might be a compatibility break.
   
   Your report is also important for  #1194: it means that all our recyclable objects (both `LogBuilder` and `ReusableMessage`) must be aware of the recycling lifecycle.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org