search

apache / logging-log4j2

Apache Log4j 2 is a versatile, feature-rich, efficient logging API and backend for Java.
https://logging.apache.org/log4j/2.x/
Apache License 2.0
3.4k stars 1.62k forks source link

`JeroMqAppenderTest` timeouts #1342

Open ppkarwasz opened 1 year ago

ppkarwasz commented 1 year ago

The JeroMqAppenderTest timeouts every other CI run on Windows.

This might be a problem with the runner's resources (TCP port), some race condition in the test, but it can be also a problem in the JeroMqAppender.

ppkarwasz commented 11 months ago

This is part of #1568.

ppkarwasz commented 8 months ago

The JeroMqAppenderTest is misbehaving again on Windows.

The relevant failure is:

2024-03-06T08:10:26.616Z main ERROR Test `testMultiThreadedServer(JeroMqAppender, LoggerContext)` has failed, dumping sta
tus data... org.opentest4j.AssertionFailedError: expected: <20> but was: <19>
        at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
        at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
        at org.junit.jupiter.api.AssertEquals.failNotEqual(AssertEquals.java:197)
        at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:150)
        at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:145)
        at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:531)
        at org.apache.logging.log4j.core.appender.mom.jeromq.JeroMqAppenderTest.testMultiThreadedServer(JeroMqAppenderTest.java:136)

The status logger gives the following messages:

2024-03-06T08:10:26.208Z main INFO Starting ZMonitor for JeroMqAppender JeroMQAppender.
2024-03-06T08:10:26.208Z pool-4-thread-1 INFO Starting JeroMqTestClient.
2024-03-06T08:10:26.208Z pool-4-thread-1 INFO Subscribing JeroMqTestClient to JeroMqAppender.
2024-03-06T08:10:26.318Z awaitility-thread INFO JeroMqAppender received an event of type ZEvent [type=HANDSHAKE_PROTOCOL, code=32768, address=tcp://0.0.0.0:56729, value=3]
2024-03-06T08:10:26.318Z pool-5-thread-1 INFO JeroMqAppender sent a message: Hello (0).
2024-03-06T08:10:26.318Z pool-5-thread-2 INFO JeroMqAppender sent a message: Hello (1).
2024-03-06T08:10:26.318Z pool-5-thread-2 INFO JeroMqAppender sent a message: Hello (1).
2024-03-06T08:10:26.318Z pool-5-thread-2 INFO JeroMqAppender sent a message: Again (1).
2024-03-06T08:10:26.318Z pool-5-thread-2 INFO JeroMqAppender sent a message: Again (1).
2024-03-06T08:10:26.318Z pool-5-thread-4 INFO JeroMqAppender sent a message: Hello (3).
2024-03-06T08:10:26.318Z pool-5-thread-4 INFO JeroMqAppender sent a message: Hello (3).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (1).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (1).
2024-03-06T08:10:26.318Z pool-5-thread-4 INFO JeroMqAppender sent a message: Again (3).
2024-03-06T08:10:26.318Z pool-5-thread-4 INFO JeroMqAppender sent a message: Again (3).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (3).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (3).
2024-03-06T08:10:26.318Z pool-5-thread-5 INFO JeroMqAppender sent a message: Hello (4).
2024-03-06T08:10:26.318Z pool-5-thread-5 INFO JeroMqAppender sent a message: Hello (4).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (4).
2024-03-06T08:10:26.318Z pool-5-thread-5 INFO JeroMqAppender sent a message: Again (4).
2024-03-06T08:10:26.318Z pool-5-thread-5 INFO JeroMqAppender sent a message: Again (4).
2024-03-06T08:10:26.318Z pool-5-thread-3 INFO JeroMqAppender sent a message: Hello (2).
2024-03-06T08:10:26.318Z pool-5-thread-3 INFO JeroMqAppender sent a message: Hello (2).
2024-03-06T08:10:26.318Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (4).
2024-03-06T08:10:26.349Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (2).
2024-03-06T08:10:26.349Z pool-5-thread-3 INFO JeroMqAppender sent a message: Again (2).
2024-03-06T08:10:26.349Z pool-5-thread-3 INFO JeroMqAppender sent a message: Again (2).
2024-03-06T08:10:26.349Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (2).
2024-03-06T08:10:26.364Z pool-5-thread-6 INFO JeroMqAppender sent a message: Hello (5).
2024-03-06T08:10:26.364Z pool-5-thread-6 INFO JeroMqAppender sent a message: Hello (5).
2024-03-06T08:10:26.364Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (5).
2024-03-06T08:10:26.364Z pool-5-thread-6 INFO JeroMqAppender sent a message: Again (5).
2024-03-06T08:10:26.364Z pool-5-thread-7 INFO JeroMqAppender sent a message: Hello (6).
2024-03-06T08:10:26.364Z pool-5-thread-7 INFO JeroMqAppender sent a message: Hello (6).
2024-03-06T08:10:26.364Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (6).
2024-03-06T08:10:26.364Z pool-5-thread-6 INFO JeroMqAppender sent a message: Again (5).
2024-03-06T08:10:26.364Z pool-5-thread-7 INFO JeroMqAppender sent a message: Again (6).
2024-03-06T08:10:26.364Z pool-5-thread-7 INFO JeroMqAppender sent a message: Again (6).
2024-03-06T08:10:26.364Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (5).
2024-03-06T08:10:26.364Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (6).
2024-03-06T08:10:26.380Z pool-5-thread-8 INFO JeroMqAppender sent a message: Hello (7).
2024-03-06T08:10:26.380Z pool-5-thread-8 INFO JeroMqAppender sent a message: Hello (7).
2024-03-06T08:10:26.380Z pool-5-thread-8 INFO JeroMqAppender sent a message: Again (7).
2024-03-06T08:10:26.380Z pool-5-thread-8 INFO JeroMqAppender sent a message: Again (7).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (7).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (7).
2024-03-06T08:10:26.380Z pool-5-thread-9 INFO JeroMqAppender sent a message: Hello (8).
2024-03-06T08:10:26.380Z pool-5-thread-9 INFO JeroMqAppender sent a message: Hello (8).
2024-03-06T08:10:26.380Z pool-5-thread-9 INFO JeroMqAppender sent a message: Again (8).
2024-03-06T08:10:26.380Z pool-5-thread-9 INFO JeroMqAppender sent a message: Again (8).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (8).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (8).
2024-03-06T08:10:26.380Z pool-5-thread-10 INFO JeroMqAppender sent a message: Hello (9).
2024-03-06T08:10:26.380Z pool-5-thread-10 INFO JeroMqAppender sent a message: Hello (9).
2024-03-06T08:10:26.380Z pool-5-thread-10 INFO JeroMqAppender sent a message: Again (9).
2024-03-06T08:10:26.380Z pool-5-thread-10 INFO JeroMqAppender sent a message: Again (9).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (9).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (9).
2024-03-06T08:10:26.380Z pool-5-thread-1 INFO JeroMqAppender sent a message: Hello (0).
2024-03-06T08:10:26.380Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Hello (0).
2024-03-06T08:10:26.489Z pool-5-thread-1 INFO JeroMqAppender sent a message: Again (0).
2024-03-06T08:10:26.489Z pool-5-thread-1 INFO JeroMqAppender sent a message: Again (0).
2024-03-06T08:10:26.489Z pool-4-thread-1 DEBUG JeroMqTestClient received a message: Again (0).
2024-03-06T08:10:26.616Z awaitility-thread INFO JeroMqAppender received an event of type ZEvent [type=DISCONNECTED, code=512, address=tcp://0.0.0.0:56729, value=3]

All seems to work out, but still it fails.

ppkarwasz commented 8 months ago

This is related to the upgrade to JeroMq 0.6.0 and may be related to zeromq/jeromq#975, although I didn't investigate it further.