Improve `SocketAppenderReconnectTest` reliability

[garydgregory]

Description

SocketAppenderReconnectTest is unreliable

SocketAppenderReconnectTest.lambda$verifyLoggingSuccess$2:360 » AppenderLogging Error writing to TCP:localhost:53217 for connection localhost/127.0.0.1:53217

Configuration

Version: 2.x at 01125b1

Operating system:
Microsoft Windows [Version 10.0.19045.4780

JDK:
Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)
Maven home: C:\java\apache-maven-3.9.9
Java version: 17.0.12, vendor: Eclipse Adoptium, runtime: C:\Program Files\Eclipse Adoptium\jdk-17.0.12.7-hotspot
Default locale: en_US, platform encoding: UTF-8
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Logs

[ERROR] Tests run: 3, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 7.934 s <<< FAILURE! -- in org.apache.logging.log4j.core.appender.SocketAppenderReconnectTest
[ERROR] org.apache.logging.log4j.core.appender.SocketAppenderReconnectTest.repeating_reconnect_failures_should_be_propagated -- Time elapsed: 2.457 s <<< ERROR!
org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to TCP:localhost:53217 for connection localhost/127.0.0.1:53217
        at org.apache.logging.log4j.core.net.TcpSocketManager.write(TcpSocketManager.java:299)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:202)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.writeByteArrayToManager(AbstractOutputStreamAppender.java:236)
        at org.apache.logging.log4j.core.appender.SocketAppender.directEncodeEvent(SocketAppender.java:598)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:714)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:672)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:648)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:584)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
        at org.apache.logging.log4j.core.Logger.log(Logger.java:240)
        at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2908)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2861)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2843)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2622)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2569)
        at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1572)
        at org.apache.logging.log4j.core.appender.SocketAppenderReconnectTest.lambda$verifyLoggingSuccess$2(SocketAppenderReconnectTest.java:360)
        at org.awaitility.core.CallableCondition$ConditionEvaluationWrapper.eval(CallableCondition.java:99)
        at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:248)
        at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:235)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.net.SocketException: Connection reset by peer
        at java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:425)
        at java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:445)
        at java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:831)
        at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1035)
        at org.apache.logging.log4j.core.net.TcpSocketManager.writeAndFlush(TcpSocketManager.java:308)
        at org.apache.logging.log4j.core.net.TcpSocketManager.write(TcpSocketManager.java:269)
        ... 29 more

Reproduction

mvn clean install

[vy]

@garydgregory, as @ppkarwasz noted in his dev@ response to you, our Develocity integration provides a dashboard where all flaky tests are visible. I don't see how creating an issue for each will help, but I guess you have a plan.

For the record, I will try to take care of SocketAppenderReconnectTest.

[garydgregory]

Personal communications are just that, they do not help the community.

My plan as it is is to signal to folks who are trying to do a simple "mvn clean install" to expect unreliable builds.

This is endlessly frustrating as the build has become more and more unreliable over time. A year or two ago, it was rare to get a failure, now it happens all the time.

I have not been able to successfully validate a release candidate in a long time. On macOS, on Windows, and on Unbuntu.

[vy]

@garydgregory, I understand your rightful frustration. We will extremely appreciate yours PRs addressing those flaky tests, it will be a great win for the community.

[vy]

@garydgregory, I am not able to reproduce this on a Windows VM, even though I had tried several times. I've pushed a commit to increase the dumped diagnostics.

1. Could you re-trigger the failure and share the complete status logs?
2. Could you check if adding @RepeatedTest(5) to repeating_reconnect_failures_should_be_propagated() helps?

[garydgregory]

Hi @vy
When I run mvn test -Dtest=SocketAppenderReconnectTest -pl log4j-core, the test is not run. How do you run tests these days?

...
[INFO] --- resources:3.3.1:testResources (default-testResources) @ log4j-core ---
[INFO] Not copying test resources
[INFO]
[INFO] --- compiler:3.13.0:testCompile (default-testCompile) @ log4j-core ---
[INFO] Not compiling test sources
[INFO]
[INFO] --- compiler:3.13.0:testCompile (generate-plugin-descriptors) @ log4j-core ---
[INFO] Not compiling test sources
[INFO]
[INFO] --- surefire:3.2.5:test (default-test) @ log4j-core ---
[INFO] Tests are skipped.
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:49 min
[INFO] Finished at: 2024-09-29T17:20:28-04:00
[INFO] ------------------------------------------------------------------------

[ppkarwasz]

@garydgregory,

Hi @vy When I run mvn test -Dtest=SocketAppenderReconnectTest -pl log4j-core, the test is not run. How do you run tests these days?

Tests were moved to log4j-core-test some time ago.

[garydgregory]

Ah... right!

[vy]

@garydgregory These (and more) are all documented in BUILDING.adoc, which is also shared in the Log4j development page too.

[garydgregory]

I pulled the latest at commit 32fb8a4 (HEAD -> 2.x, origin/2.x)
I does not happen after I run:

mvn test -Dtest=SocketAppenderReconnectTest -pl log4j-core-test

But when I run:

mvn clean verify

I get:

[INFO] Baseline bundle C:\Users\ggregory\git\a\logging-log4j2\log4j-core\target\log4j-core-2.25.0-SNAPSHOT.jar against baseline C:\Users\ggregory\.m2\repository\org\apache\logging\log4j\log4j-core\2.24.1\log4j-core-2.24.1.jar
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for Apache Log4j BOM 2.25.0-SNAPSHOT:
[INFO]
[INFO] Apache Log4j BOM ................................... SUCCESS [ 44.849 s]
[INFO] Apache Log4j Parent ................................ SUCCESS [  2.240 s]
[INFO] Apache Log4j API Java 9 support .................... SUCCESS [ 12.675 s]
[INFO] Apache Log4j API ................................... SUCCESS [ 34.539 s]
[INFO] Apache Log4j Implementation Java 9 support ......... SUCCESS [  9.690 s]
[INFO] Apache Log4j Core .................................. FAILURE [01:48 min]
[INFO] Apache Log4j API Tests ............................. SKIPPED
[INFO] Apache Log4j Core Tests ............................ SKIPPED
[INFO] Apache Log4j 1.x Compatibility API ................. SKIPPED
[INFO] Apache Log4j App Server Support .................... SKIPPED
[INFO] Log4j API to SLF4J Adapter ......................... SKIPPED
[INFO] SLF4J 1 Binding for Log4j API ...................... SKIPPED
[INFO] Apache Log4j Cassandra ............................. SKIPPED
[INFO] Apache Log4j fuzz tests ............................ SKIPPED
[INFO] Apache Log4j Core fuzz tests ....................... SKIPPED
[INFO] Apache Log4j Core Integration Tests ................ SKIPPED
[INFO] Apache Log4j CouchDB ............................... SKIPPED
[INFO] Apache Log4j Docker Library ........................ SKIPPED
[INFO] Apache Log4j Streaming Interface ................... SKIPPED
[INFO] Apache Log4j Jakarta SMTP .......................... SKIPPED
[INFO] Apache Log4j Jakarta Web ........................... SKIPPED
[INFO] Apache Log4j Commons Logging Bridge ................ SKIPPED
[INFO] Apache Log4j JPA ................................... SKIPPED
[INFO] Apache Log4j JDK Platform Logging Adapter .......... SKIPPED
[INFO] Apache Log4j JDBC DBCP 2 ........................... SKIPPED
[INFO] Apache Log4j JUL Adapter ........................... SKIPPED
[INFO] Apache Log4j JSON Template Layout .................. SKIPPED
[INFO] Apache Log4j JSON Template Layout fuzz tests ....... SKIPPED
[INFO] Apache Log4j JSON Template Layout tests ............ SKIPPED
[INFO] Apache Log4j MongoDB 4 ............................. SKIPPED
[INFO] Apache Log4j MongoDB Appender ...................... SKIPPED
[INFO] Apache Log4j to JUL Bridge ......................... SKIPPED
[INFO] Apache Log4j OSGi tests ............................ SKIPPED
[INFO] Apache Log4J Performance Tests ..................... SKIPPED
[INFO] SLF4J 2 Provider for Log4j API ..................... SKIPPED
[INFO] SLF4J 2 Provider for Log4j API fuzz tests .......... SKIPPED
[INFO] Apache Log4j Spring Boot Support ................... SKIPPED
[INFO] Apache Log4j Spring Cloud Config Client Support .... SKIPPED
[INFO] Apache Log4j Web ................................... SKIPPED
[INFO] Apache Log4j Tag Library ........................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  03:33 min
[INFO] Finished at: 2024-09-30T08:50:09-04:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal biz.aQute.bnd:bnd-baseline-maven-plugin:7.0.0:baseline (check-api-compat) on project log4j-core: An error occurred while calculating the baseline: Baseline problems detected. See the report in C:\Users\ggregory\git\a\logging-log4j2\log4j-core\target\baseline\log4j-core-2.25.0-SNAPSHOT.txt.
[ERROR] ===============================================================
[ERROR]   Name                                               Type       Delta      New        Old        Suggest
[ERROR]   org.apache.logging.log4j.core                      BUNDLE     MAJOR      2.25.0.SNAPSHOT 2.24.1     -
[ERROR] ===============================================================
[ERROR]   Name                                               Type       Delta      New        Old        Suggest    If Prov.
[ERROR]   org.apache.logging.log4j.core                      PACKAGE    MICRO      2.25.0     2.24.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender             PACKAGE    UNCHANGED  2.20.3     2.20.3     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.db          PACKAGE    UNCHANGED  2.21.0     2.21.0     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.db.jdbc     PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.mom         PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.mom.jeromq  PACKAGE    UNCHANGED  2.21.0     2.21.0     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.mom.kafka   PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.nosql       PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.rewrite     PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.rolling     PACKAGE    UNCHANGED  2.21.1     2.21.1     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.rolling.action PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.appender.routing     PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.async                PACKAGE    MICRO      2.25.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.config               PACKAGE    UNCHANGED  2.24.1     2.24.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.arbiters      PACKAGE    UNCHANGED  2.21.0     2.21.0     ok         -
[ERROR]   org.apache.logging.log4j.core.config.builder.api   PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.builder.impl  PACKAGE    UNCHANGED  2.20.2     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.config.composite     PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.json          PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins       PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.convert PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.processor PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.util  PACKAGE    UNCHANGED  2.20.2     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.validation PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.validation.constraints PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.validation.validators PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.plugins.visitors PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.properties    PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.config.status        PACKAGE    UNCHANGED  2.20.2     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.config.xml           PACKAGE    UNCHANGED  2.20.2     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.config.yaml          PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.filter               PACKAGE    UNCHANGED  2.21.1     2.21.1     ok         -
[ERROR]   org.apache.logging.log4j.core.filter.mutable       PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.impl                 PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.jackson              PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.jmx                  PACKAGE    UNCHANGED  2.23.0     2.23.0     ok         -
[ERROR]   org.apache.logging.log4j.core.layout               PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.lookup               PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.net                  PACKAGE    UNCHANGED  2.20.3     2.20.3     ok         -
[ERROR]   org.apache.logging.log4j.core.net.ssl              PACKAGE    MICRO      2.25.0     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.osgi                 PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.parser               PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.pattern              PACKAGE    UNCHANGED  2.24.0     2.24.0     ok         -
[ERROR]   org.apache.logging.log4j.core.script               PACKAGE    UNCHANGED  2.20.2     2.20.2     ok         -
[ERROR]   org.apache.logging.log4j.core.selector             PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.time                 PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR]   org.apache.logging.log4j.core.tools                PACKAGE    UNCHANGED  2.20.1     2.20.1     ok         -
[ERROR] * org.apache.logging.log4j.core.util                 PACKAGE    CHANGED    2.24.1     2.24.1     2.24.2     -
[ERROR]   CHANGED              PACKAGE    org.apache.logging.log4j.core.util
[ERROR]     CHANGED            CLASS      org.apache.logging.log4j.core.util.Loader
[ERROR]       CHANGED          METHOD     getResource(java.lang.String,java.lang.ClassLoader)
[ERROR]         ADDED          ANNOTATED  org.jspecify.annotations.Nullable
[ERROR]     CHANGED            CLASS      org.apache.logging.log4j.core.util.Source
[ERROR]       CHANGED          METHOD     getFile()
[ERROR]         ADDED          ANNOTATED  org.jspecify.annotations.Nullable
[ERROR]       ADDED            ANNOTATED  org.jspecify.annotations.NullMarked
[ERROR]   org.apache.logging.log4j.core.util.datetime        PACKAGE    UNCHANGED  2.21.1     2.21.1     ok         -
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR]   mvn <args> -rf :log4j-core

[ppkarwasz]

[ERROR] * org.apache.logging.log4j.core.util                 PACKAGE    CHANGED    2.24.1     2.24.1     2.24.2     -
[ERROR]   CHANGED              PACKAGE    org.apache.logging.log4j.core.util
[ERROR]     CHANGED            CLASS      org.apache.logging.log4j.core.util.Loader
[ERROR]       CHANGED          METHOD     getResource(java.lang.String,java.lang.ClassLoader)
[ERROR]         ADDED          ANNOTATED  org.jspecify.annotations.Nullable
[ERROR]     CHANGED            CLASS      org.apache.logging.log4j.core.util.Source
[ERROR]       CHANGED          METHOD     getFile()
[ERROR]         ADDED          ANNOTATED  org.jspecify.annotations.Nullable
[ERROR]       ADDED            ANNOTATED  org.jspecify.annotations.NullMarked
[ERROR]   org.apache.logging.log4j.core.util.datetime        PACKAGE    UNCHANGED  2.21.1     2.21.1     ok         -

I fixed it yesterday in 9de91b8.

Should we have a troubleshooting page for the build? Where can I add it?

Regarding BND baseline problems, there are a couple of rules to keep in mind. If a package foo.bar.baz has version 1.2.3 and we are currently working on version 7.8.9-SNAPSHOT of foo.jar:

• If BND Baseline proposes to bump the version of foo.bar.baz to 1.2.4, we do just that in foo/bar/baz/package-info.java,
• If BND Baseline proposes to bump the version to 1.3.0 (MINOR version bump), we bump the version of foo.jar to 7.9.0-SNAPSHOT and the version of the foo.bar.baz package to 7.9.0. This way the version of the package registers the last version of foo.jar with important modifications to the package.
• If BND Baseline proposes to bump the version to 2.0.0 (MAJOR version bump), we must remove the breaking changes or start a 8.0.0 branch.

[garydgregory]

@ppkarwasz You said you fixed it yesterday but I just pulled 30 minutes ago before commenting about the failure, so I'm confused!