Skip to content

ReusableMessages not getting released when using entry/exit logging #1273

Open
@davemessink

Description

@davemessink

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);
    }

Metadata

Metadata

Assignees

Labels

bugIncorrect, unexpected, or unintended behavior of existing code

Type

No type

Projects

No projects

Relationships

None yet

Development

No branches or pull requests

Issue actions