Skip to content

Improve runtime and reduce log output for SSLCertificateTest#1215

Draft
Copilot wants to merge 12 commits intomasterfrom
copilot/improve-ssl-certificatetest-runtime
Draft

Improve runtime and reduce log output for SSLCertificateTest#1215
Copilot wants to merge 12 commits intomasterfrom
copilot/improve-ssl-certificatetest-runtime

Conversation

Copy link
Copy Markdown
Contributor

Copilot AI commented May 6, 2026

SSLCertificateTest was consuming ~20 of the CI job's ~45 minutes, logging ~45k of ~120k log lines. Four targeted fixes:

Timeout and heartbeat tuning

  • TIMEOUT_SECONDS: 15s → 7s
  • HeartBtInt: 30s → 5s across all session settings builders — a heartbeat exchange within the window is sufficient to confirm a healthy session

Reduce log noise for expected failures

  • volatile boolean exceptionExpected flag on TestConnector, starts false
  • Added expectException() method to TestConnector — called on each connector immediately after construction and before start() in all shouldFailWhen* methods
  • The MINA filter in prepareConnector checks the flag in exceptionCaught: logs message-only when true, full stack trace when false
  • Connectors used in non-failure tests never have the flag set, preserving full traces for unexpected failures

This cuts the bulk of log output generated by shouldFailWhen* tests.

Parallel no-exception checks

Added assertNoSslExceptionsThrown(TestConnector... connectors) — runs each connector's latch-wait concurrently instead of sequentially. For a test with N connectors this replaces N×7s with a single 7s wait.

// before: sequential, each blocks for up to 7s
initiator.assertNoSslExceptionThrown();
// ... initiator assertions ...
acceptor.assertNoSslExceptionThrown();

// after: single concurrent wait
assertNoSslExceptionsThrown(initiator, acceptor);
// ... initiator and acceptor assertions ...

Threads are named (ssl-check<Type><index>) for debuggability. On failure, a composite error message summarises all failures upfront with individual errors as suppressed exceptions. Applied across 15 test methods.

Test name logging

Added a class-level LOGGER and a @Rule TestName field to SSLCertificateTest. The existing @Before setUp() now logs >>> Running test: <methodName> before every test, making it easy to correlate log output with the active test method in CI logs.

Copilot AI and others added 2 commits May 6, 2026 11:15
…rallelize no-exception checks

Agent-Logs-Url: https://github.com/quickfix-j/quickfixj/sessions/f464dac4-ab03-4de1-a750-fbcb1d6bd19c

Co-authored-by: chrjohn <6644028+chrjohn@users.noreply.github.com>
Copilot AI changed the title [WIP] Improve runtime for SSLCertificateTest Improve runtime for SSLCertificateTest May 6, 2026
Copilot AI requested a review from chrjohn May 6, 2026 11:21
Copilot finished work on behalf of chrjohn May 6, 2026 11:21
@Override
public void exceptionCaught(NextFilter nextFilter, IoSession session, Throwable cause) {
LOGGER.info("exceptionCaught", cause);
LOGGER.info("exceptionCaught: {}", cause.getMessage());
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@copilot this reduces the exceptions for ALL cases, not only when they are expected.
When an exception is expected: log only the message.
When no exception is expected and an exception occurs: log the exception with stack trace.
An exception is expected when assertSslExceptionThrown is called on a connector. That connector then needs to be initialized with a boolean flag or similar so that the exceptionCaught handler knows when to log the full exception with stack trace or just the message.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in 433a0d5. Added a volatile boolean exceptionExpected flag to TestConnector. assertSslExceptionThrown sets it to true before waiting on the latch. The exceptionCaught handler now logs message-only when exceptionExpected is true, and the full stack trace otherwise.

Copilot finished work on behalf of chrjohn May 6, 2026 13:51
Copilot AI requested a review from chrjohn May 6, 2026 13:51
Copilot finished work on behalf of chrjohn May 6, 2026 15:07
@chrjohn chrjohn changed the title Improve runtime for SSLCertificateTest Improve runtime for SSLCertificateTest May 6, 2026
@chrjohn chrjohn changed the title Improve runtime for SSLCertificateTest Improve runtime and log output for SSLCertificateTest May 6, 2026
Copilot finished work on behalf of chrjohn May 6, 2026 15:48
Refactor createDefaults method to initialize defaults directly.
Copilot stopped work on behalf of chrjohn due to an error May 6, 2026 17:05
@chrjohn chrjohn changed the title Improve runtime and log output for SSLCertificateTest Improve runtime and reduce log output for SSLCertificateTest May 6, 2026
@chrjohn chrjohn added this to the QFJ 3.0.1 milestone May 7, 2026
@chrjohn
Copy link
Copy Markdown
Member

chrjohn commented May 7, 2026

@copilot looking good so far. However, there still are many expected exceptions logged since we set exceptionExpected=true too late. We set it in the assert* methods. However, we can encounter expected exceptions already when connecting. So this needs to be changed so that we set the exceptionExpected flag on the testconnector before invoking start() on it. This should apply to all connectors that are used in shouldFailWhen... methods.

Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 7, 2026

@copilot looking good so far. However, there still are many expected exceptions logged since we set exceptionExpected=true too late. We set it in the assert* methods. However, we can encounter expec...

Fixed in f66e237. Added expectException() to TestConnector and call it on each connector immediately after construction (before start()) in all 6 shouldFailWhen* methods. Also removed the exceptionExpected = true from assertNotAuthenticated, which was incorrectly suppressing stack traces in non-failure tests that also call that method.

Copilot finished work on behalf of chrjohn May 7, 2026 14:47
@chrjohn
Copy link
Copy Markdown
Member

chrjohn commented May 7, 2026

@copilot

  1. Please add logging to each test method so that I can see in the logs which test is currently active. That way I could identify where still too much is logged.
  2. Please update PR description with all changes done, e.g. section "reduce log noise" is not correct since we use a flag on the connector now.

Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 7, 2026

@copilot

  1. Please add logging to each test method so that I can see in the logs which test is currently active. That way I could identify where still too much is logged.
  2. Please update PR descri...

Done in dd263e0:

  1. Added a class-level LOGGER and @Rule public final TestName testName to SSLCertificateTest. The @Before setUp() now logs >>> Running test: <methodName> before every test — covers all 24 methods with a single change. Since the test is parameterized, the logged name also includes the parameter set (e.g. shouldAuthenticateServerCertificate[0]).

  2. Updated the PR description to accurately reflect all changes, including the expectException() / before-start() pattern replacing the old description of setting the flag in assertSslExceptionThrown.

Copilot finished work on behalf of chrjohn May 7, 2026 15:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Runtime and log output for SSLCertificateTest needs to be improved

2 participants