-
Notifications
You must be signed in to change notification settings - Fork 625
jdbc-v2: swallow chunked-stream drain errors on ResultSet.close (fixes #2361) #2857
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from 2 commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,127 @@ | ||
| package com.clickhouse.examples.jdbc; | ||
|
|
||
| import java.io.PrintWriter; | ||
| import java.io.StringWriter; | ||
| import java.sql.Connection; | ||
| import java.sql.DriverManager; | ||
| import java.sql.ResultSet; | ||
| import java.sql.SQLException; | ||
| import java.sql.Statement; | ||
| import java.util.Properties; | ||
| import java.util.concurrent.atomic.AtomicInteger; | ||
|
|
||
| /** | ||
| * Reproducer for issue #2361 — ConnectionClosedException: "Premature end of | ||
| * chunk coded message body: closing chunk expected" during ResultSet.close(). | ||
| * | ||
| * <p>Recipe: | ||
| * <ol> | ||
| * <li>Configure the JDBC connection with LZ4 HTTP compression on | ||
| * ({@code compress=true&client.use_http_compression=true}) and a | ||
| * short server-side {@code send_timeout=1} so the server abandons | ||
| * writes after one second of back-pressure.</li> | ||
| * <li>Force the server to commit to chunked HTTP encoding by buffering | ||
| * the full response: {@code http_response_buffer_size=104857600} | ||
| * and {@code wait_end_of_query=1}.</li> | ||
| * <li>Issue a query whose result is large enough to overflow the buffer | ||
| * and that a slow client cannot drain in time.</li> | ||
| * <li>Read rows slowly (a few {@code Thread.sleep}s per thousand rows).</li> | ||
| * </ol> | ||
| * | ||
| * <p>The server hits {@code SOCKET_TIMEOUT} writing the chunked body, closes | ||
| * the connection without emitting the terminating zero-length chunk, and | ||
| * the driver's stream-drain on close trips the exception. | ||
| * | ||
| * <p>Run with: {@code java -DchUrl=jdbc:ch://localhost:8123 com.clickhouse.examples.jdbc.Issue2361Repro [iters]} | ||
| * | ||
| * <p>The fix in {@code ResultSetImpl.close()} downgrades this drain-time | ||
| * failure to a debug log instead of a thrown SQLException — close() should | ||
| * never punish callers for a server-side teardown race after iteration is done. | ||
| */ | ||
| public class Issue2361Repro { | ||
|
|
||
| // 5M rows × ~4.5KB pad ≈ 22 GB uncompressed (~700 MB lz4-compressed). | ||
| // Large enough that send_timeout=1 + slow client reliably triggers the bug | ||
| // in a freshly-started server (before its memory tracker fills with prior | ||
| // query state). | ||
| static final String QUERY = | ||
| "SELECT number, repeat('xyz', 1500) AS pad FROM numbers(5000000)"; | ||
|
|
||
| public static void main(String[] args) throws Exception { | ||
| Class.forName("com.clickhouse.jdbc.Driver"); | ||
|
|
||
| String baseUrl = System.getProperty("chUrl", "jdbc:ch://localhost:8123") + "/default"; | ||
| int iters = args.length > 0 ? Integer.parseInt(args[0]) : 3; | ||
|
|
||
| Properties props = new Properties(); | ||
| props.setProperty("user", System.getProperty("chUser", "default")); | ||
| props.setProperty("password", System.getProperty("chPassword", "")); | ||
| // Compression on — same lz4-framed-over-HTTP path observed in the bug. | ||
| props.setProperty("compress", "true"); | ||
| props.setProperty("client.use_http_compression", "true"); | ||
| // Long socket timeout so we don't bail out before the bug surfaces. | ||
| props.setProperty("socket_timeout", "60000"); | ||
| // Trigger conditions: | ||
| props.setProperty("clickhouse_setting_send_timeout", "1"); | ||
| props.setProperty("clickhouse_setting_http_response_buffer_size", "104857600"); | ||
| props.setProperty("clickhouse_setting_wait_end_of_query", "1"); | ||
| props.setProperty("clickhouse_setting_max_execution_time", "120"); | ||
|
|
||
| AtomicInteger trips = new AtomicInteger(); | ||
| String firstStack = null; | ||
|
|
||
| for (int i = 0; i < iters; i++) { | ||
| long t0 = System.currentTimeMillis(); | ||
| try (Connection c = DriverManager.getConnection(baseUrl, props); | ||
| Statement s = c.createStatement(); | ||
| ResultSet rs = s.executeQuery(QUERY)) { | ||
|
|
||
| int rows = 0; | ||
| try { | ||
| while (rs.next()) { | ||
| rs.getString(2); | ||
| rows++; | ||
| // Slow client: ~1 s per ~1000 rows → 5,000 s to fully | ||
| // drain. Server send_timeout=1 will fire well before then. | ||
| if (rows % 100 == 0) Thread.sleep(50); | ||
| } | ||
| } catch (SQLException re) { | ||
| // Mid-iteration errors land here; the bug we want is the | ||
| // try-with-resources close that fires after the catch. | ||
| } | ||
| } catch (Throwable t) { | ||
| if (hasInMsg(t, "Premature end of chunk")) { | ||
| trips.incrementAndGet(); | ||
| if (firstStack == null) firstStack = stack(t); | ||
| } | ||
| } | ||
| System.out.printf("iter %d: trips=%d elapsed=%dms%n", | ||
| i, trips.get(), System.currentTimeMillis() - t0); | ||
| System.out.flush(); | ||
| } | ||
|
|
||
| System.out.printf("%nFINAL: trips=%d / %d iterations (%.0f%%)%n", | ||
| trips.get(), iters, 100.0 * trips.get() / iters); | ||
| if (firstStack != null) { | ||
| System.out.println("\n-- first failure stack (top frames) --"); | ||
| String[] lines = firstStack.split("\n"); | ||
| for (int li = 0; li < Math.min(24, lines.length); li++) { | ||
| System.out.println(lines[li]); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| private static boolean hasInMsg(Throwable t, String needle) { | ||
| while (t != null) { | ||
| if (t.getMessage() != null && t.getMessage().contains(needle)) return true; | ||
| t = t.getCause(); | ||
| } | ||
| return false; | ||
| } | ||
|
|
||
| private static String stack(Throwable t) { | ||
| StringWriter sw = new StringWriter(); | ||
| t.printStackTrace(new PrintWriter(sw)); | ||
| return sw.toString(); | ||
| } | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -149,14 +149,28 @@ public boolean next() throws SQLException { | |
| public void close() throws SQLException { | ||
| closed = true; | ||
|
|
||
| // Stream-close exceptions on the response body are expected when the server has | ||
| // already torn down the connection (e.g. SOCKET_TIMEOUT on the writer side hits | ||
| // `send_timeout` before the terminating chunk is written). The most common | ||
| // surface is `ConnectionClosedException: Premature end of chunk coded message | ||
| // body: closing chunk expected` from Apache HC's `ChunkedInputStream` drain, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. please explain in 3 lines comment.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. ResultSetImpl.close() is reverted to its original shape — the long comment is gone entirely. The drain handling moved into client-v2 (AbstractBinaryFormatReader.close), and the 6-line WHY now lives there, at the actual catch site. ResultSetImpl just propagates whatever the reader gives it, like before. |
||
| // optionally wrapped through `FramedLZ4CompressorInputStream` when the | ||
| // response was lz4-compressed. The application has already finished iterating | ||
| // the result set; propagating the drain failure as a SQLException punishes | ||
| // well-behaved try-with-resources callers for a server-side socket race they | ||
| // cannot affect. Log at debug and swallow -- the connection is closed either | ||
| // way, and we should not turn `try (ResultSet rs = ...)` into a throwing path. | ||
| // See https://github.com/ClickHouse/clickhouse-java/issues/2361 | ||
| Exception e = null; | ||
| try { | ||
| if (reader != null) { | ||
| try { | ||
| reader.close(); | ||
| } catch (Exception re) { | ||
| log.debug("Error closing reader", re); | ||
| e = re; | ||
| if (!isStreamDrainException(re)) { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. this should be handled in client-v2.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Moved to client-v2. Drain handling now lives in |
||
| e = re; | ||
| } | ||
| } finally { | ||
| reader = null; | ||
| } | ||
|
|
@@ -167,7 +181,9 @@ public void close() throws SQLException { | |
| response.close(); | ||
| } catch (Exception re) { | ||
| log.debug("Error closing response", re); | ||
| e = re; | ||
| if (!isStreamDrainException(re)) { | ||
| e = re; | ||
| } | ||
| } finally { | ||
| response = null; | ||
| } | ||
|
|
@@ -180,6 +196,33 @@ public void close() throws SQLException { | |
| } | ||
| } | ||
|
|
||
| /** | ||
| * Determines whether a close-time exception originates from draining an | ||
| * already-truncated HTTP chunked response body. Such exceptions are not | ||
| * actionable from the caller's perspective -- iteration has finished, the | ||
| * connection is closing anyway, and the server's premature disconnect is the | ||
| * actual error condition (which, if it occurred during iteration, would have | ||
| * surfaced through {@code next()}). | ||
| */ | ||
| // Package-private for unit tests. | ||
| static boolean isStreamDrainException(Throwable t) { | ||
| while (t != null) { | ||
| String msg = t.getMessage(); | ||
| if (msg != null && (msg.contains("Premature end of chunk") | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. we should detect that it is
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Done. The detection is now class-based — walks the cause chain and matches |
||
| || msg.contains("closing chunk expected"))) { | ||
| return true; | ||
| } | ||
| // ConnectionClosedException + class name match for defensive coverage of | ||
| // future HC versions that may rephrase the message. | ||
| String cls = t.getClass().getName(); | ||
| if (cls.endsWith("ConnectionClosedException")) { | ||
| return true; | ||
| } | ||
| t = t.getCause(); | ||
| } | ||
| return false; | ||
| } | ||
|
|
||
| @Override | ||
| public boolean wasNull() throws SQLException { | ||
| checkClosed(); | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,72 @@ | ||
| package com.clickhouse.jdbc; | ||
|
|
||
| import org.testng.annotations.Test; | ||
|
|
||
| import java.io.IOException; | ||
|
|
||
| import static org.testng.Assert.assertFalse; | ||
| import static org.testng.Assert.assertTrue; | ||
|
|
||
| /** | ||
| * Unit tests for ResultSetImpl.isStreamDrainException — the classifier that | ||
| * decides whether a close-time exception is a benign chunked-stream drain | ||
| * failure (to swallow) or a real error (to propagate). | ||
| * | ||
| * Background: see issue #2361. When the server's send_timeout fires mid-write, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This should document scenario without reference to issue in external system (issue may gone).
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Done — the test file is gone, replaced by AbstractBinaryFormatReaderCloseTest in client-v2 whose javadoc describes the scenario (server tearing down the connection before the terminating zero-length chunk is written) with no reference to an external issue tracker. The production-side WHY now lives in AbstractBinaryFormatReader.close(), which is the starting point when investigating. |
||
| * Apache HC's ChunkedInputStream.close() trips | ||
| * `ConnectionClosedException: Premature end of chunk coded message body: | ||
| * closing chunk expected`. That happens during ResultSetImpl.close(), AFTER | ||
| * the application has finished iterating. Propagating it punishes well-behaved | ||
| * try-with-resources callers for a server-side socket race they cannot affect. | ||
| */ | ||
| public class ResultSetImplCloseTest { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please squash into a fewer tests and move to
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Squashed and moved. Since the close-time handling now lives in client-v2 (AbstractBinaryFormatReader.close) rather than jdbc-v2, the tests followed: 6 unit tests collapsed into a single data-driven test (AbstractBinaryFormatReaderCloseTest) in client-v2. Marked the |
||
|
|
||
| @Test | ||
| public void prematureEndOfChunkIsDrainException() { | ||
| // The canonical surface from issue #2361. | ||
| Exception e = new IOException("Premature end of chunk coded message body: closing chunk expected"); | ||
| assertTrue(ResultSetImpl.isStreamDrainException(e)); | ||
| } | ||
|
|
||
| @Test | ||
| public void closingChunkExpectedIsDrainException() { | ||
| // Forward-compat for variations of the same message. | ||
| Exception e = new IOException("...closing chunk expected"); | ||
| assertTrue(ResultSetImpl.isStreamDrainException(e)); | ||
| } | ||
|
|
||
| @Test | ||
| public void wrappedCausesAreUnwrapped() { | ||
| // Stack from the actual JDBC trace: | ||
| // SQLException -> ClientException -> ConnectionClosedException | ||
| Throwable root = new FakeConnectionClosedException("Premature end of chunk coded message body: closing chunk expected"); | ||
| RuntimeException mid = new RuntimeException("Failed to close response", root); | ||
| Exception top = new Exception("wrapped", mid); | ||
| assertTrue(ResultSetImpl.isStreamDrainException(top)); | ||
| } | ||
|
|
||
| @Test | ||
| public void classNameMatchEvenWithoutMessage() { | ||
| // Defensive: if a future HC version drops the descriptive message but | ||
| // keeps the exception class, we still want to classify it as drain noise. | ||
| Throwable e = new FakeConnectionClosedException(null); | ||
| assertTrue(ResultSetImpl.isStreamDrainException(e)); | ||
| } | ||
|
|
||
| @Test | ||
| public void unrelatedExceptionsArePropagated() { | ||
| assertFalse(ResultSetImpl.isStreamDrainException(new IOException("disk full"))); | ||
| assertFalse(ResultSetImpl.isStreamDrainException(new IllegalStateException("bad state"))); | ||
| assertFalse(ResultSetImpl.isStreamDrainException(new RuntimeException("anything else"))); | ||
| } | ||
|
|
||
| @Test | ||
| public void nullThrowableHandled() { | ||
| assertFalse(ResultSetImpl.isStreamDrainException(null)); | ||
| } | ||
|
|
||
| /** Mimics org.apache.hc.core5.http.ConnectionClosedException for the class-name match. */ | ||
| private static final class FakeConnectionClosedException extends IOException { | ||
| FakeConnectionClosedException(String msg) { super(msg); } | ||
| } | ||
| } | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This should be a test. Examples are only for documentation purpose.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Removed. The Issue2361Repro example has been deleted in the latest commit. The trigger recipe (compress=true, server send_timeout=1, buffered chunked response, slow client read) is now documented inline at the detection site in AbstractBinaryFormatReader.close().