Skip to content

Commit 62cdcd0

Browse files
chernserchernser
authored
Merge pull request #2973 from ClickHouse/polyglot/fix-bad-logging-2970
[client-v2, jdbc-v2] Fix bad and noisy logging (#2970)
2 parents 9019d77 + 350f880 commit 62cdcd0

16 files changed

Lines changed: 269 additions & 41 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,8 @@
3535

3636
### Bug Fixes
3737

38+
- **[client-v2, jdbc-v2]** Reduced noisy and potentially sensitive logging; SQL that fails to parse is no
39+
longer logged at `WARN` (it could contain credentials/PII). (https://github.com/ClickHouse/clickhouse-java/issues/2970)
3840
- **[client-v2]** Fixed `BigDecimal` values written into a `Dynamic` column being silently truncated when the
3941
value's scale exceeded the inferred width's maximum scale, and throwing an overflow error when the value
4042
carried an integer part (e.g. `19.99`). The `Dynamic` type inference now sizes the `Decimal` width to hold
@@ -47,7 +49,6 @@
4749
serialized identically to its underlying type `T`, writing the `Nullable` null-marker byte when the
4850
underlying type is nullable (e.g. `SimpleAggregateFunction(anyLast, Nullable(String))`), mirroring the
4951
read path. (https://github.com/ClickHouse/clickhouse-java/issues/2477)
50-
5152
- **[client-v2, jdbc-v2]** Fixed several logging-layer defects. In `client-v2`, `HttpAPIClientHelper.shouldRetry`
5253
threw a `ClassCastException` when a retryable `ServerException` was wrapped as the *cause* of another exception
5354
(the branch matched on the cause but the cast used the outer exception); the retry decision is now taken from

‎client-v2/src/main/java/com/clickhouse/client/api/Client.java‎

Lines changed: 16 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1499,8 +1499,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,
14991499
lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
15001500
if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(queryId)) {
15011501
if (i < maxAttempts) {
1502-
LOG.warn("Retrying.", e);
1503-
selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
1502+
selectedEndpoint = logRetryAndSelectNextNode("Insert", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
15041503
} else {
15051504
nodeSelector.getNextAliveNode(selectedEndpoint);
15061505
}
@@ -1705,8 +1704,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,
17051704
lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
17061705
if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(requestSettings.getQueryId())) {
17071706
if (i < maxAttempts) {
1708-
LOG.warn("Retrying.", e);
1709-
selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
1707+
selectedEndpoint = logRetryAndSelectNextNode("Insert (stream)", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
17101708
} else {
17111709
nodeSelector.getNextAliveNode(selectedEndpoint);
17121710
}
@@ -1849,8 +1847,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
18491847
lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
18501848
if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(requestSettings.getQueryId())) {
18511849
if (i < maxAttempts) {
1852-
LOG.warn("Retrying.", e);
1853-
selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
1850+
selectedEndpoint = logRetryAndSelectNextNode("Query", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
18541851
} else {
18551852
nodeSelector.getNextAliveNode(selectedEndpoint);
18561853
}
@@ -1871,6 +1868,19 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
18711868
return runAsyncOperation(responseSupplier, requestSettings.getAllSettings());
18721869
}
18731870

1871+
/**
1872+
* Logs a single consolidated warning for a failed but retryable request attempt and returns
1873+
* the next endpoint to try. Keeping this in one place ensures a retry is logged exactly once
1874+
* with a consistent shape across the insert and query paths.
1875+
*/
1876+
private Endpoint logRetryAndSelectNextNode(String operation, int attemptIndex, int maxAttempts,
1877+
String queryId, Endpoint endpoint, Exception cause) {
1878+
LOG.warn("{} failed (attempt {} of {}, queryId: {}), endpoint: {}, cause: {}: {}. Retrying.",
1879+
operation, attemptIndex + 1, maxAttempts + 1, queryId, endpoint,
1880+
cause.getClass().getName(), cause.getMessage());
1881+
return nodeSelector.getNextAliveNode(endpoint);
1882+
}
1883+
18741884
private void registerTransportReq(String queryId, TransportRequest tr) {
18751885
if (queryId != null) {
18761886
ongoingRequests.put(queryId, tr);

‎client-v2/src/main/java/com/clickhouse/client/api/internal/ClickHouseLZ4InputStream.java‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ public class ClickHouseLZ4InputStream extends InputStream {
2727

2828
public ClickHouseLZ4InputStream(InputStream in, LZ4FastDecompressor decompressor, int bufferSize) {
2929
super();
30-
LOG.debug("Using decompressor {}", decompressor);
30+
LOG.debug("Using LZ4 decompressor with buffer size {}", bufferSize);
3131
this.decompressor = decompressor;
3232
this.in = in;
3333
this.buffer = ByteBuffer.allocate(bufferSize);
@@ -137,7 +137,6 @@ private int refill() throws IOException {
137137

138138
if (buffer.capacity() < uncompressedSize) {
139139
buffer = ByteBuffer.allocate(uncompressedSize);
140-
LOG.debug("Buffer size is too small, reallocate buffer with size: {}", uncompressedSize);
141140
}
142141
decompressor.decompress(ByteBuffer.wrap(block), offset, buffer, 0, uncompressedSize);
143142
buffer.position(0);

‎client-v2/src/main/java/com/clickhouse/client/api/internal/ClickHouseLZ4OutputStream.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ public class ClickHouseLZ4OutputStream extends OutputStream {
2929

3030
public ClickHouseLZ4OutputStream(OutputStream out, LZ4Compressor compressor, int bufferSize) {
3131
super();
32-
LOG.debug("Using compressor {}", compressor);
32+
LOG.debug("Using LZ4 compressor with buffer size {}", bufferSize);
3333
this.inBuffer = ByteBuffer.allocate(bufferSize);
3434
this.out = out;
3535
this.compressor = compressor;

‎client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java‎

Lines changed: 2 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -734,10 +734,10 @@ public TransportResponse executeRequest(TransportRequest transportRequest) throw
734734
throw new ClientException("Unexpected result status " + statusCode);
735735
}
736736
} catch (UnknownHostException e) {
737-
LOG.warn("Host '{}' unknown", req.getAuthority());
737+
LOG.debug("Host '{}' unknown", req.getAuthority());
738738
throw e;
739739
} catch (ConnectException | NoRouteToHostException e) {
740-
LOG.warn("Failed to connect to '{}': {}", req.getAuthority(), e.getMessage());
740+
LOG.debug("Failed to connect to '{}': {}", req.getAuthority(), e.getMessage());
741741
throw e;
742742
} catch (Exception e) {
743743
LOG.debug("Failed to execute request to '{}': {}", req.getAuthority(), e.getMessage(), e);
@@ -938,9 +938,6 @@ private HttpEntity wrapRequestEntity(HttpEntity httpEntity, Map<String, Object>
938938
boolean useHttpCompression = ClientConfigProperties.USE_HTTP_COMPRESSION.getOrDefault(requestConfig);
939939
boolean appCompressedData = ClientConfigProperties.APP_COMPRESSED_DATA.getOrDefault(requestConfig);
940940

941-
LOG.debug("wrapRequestEntity: client compression: {}, http compression: {}, content encoding: {}",
942-
clientCompression, useHttpCompression, httpEntity.getContentEncoding());
943-
944941
if (httpEntity.getContentEncoding() != null && !appCompressedData) {
945942
// http header is set and data is not compressed
946943
return new CompressedEntity(httpEntity, false, CompressorStreamFactory.getSingleton());
@@ -957,9 +954,6 @@ private HttpEntity wrapResponseEntity(HttpEntity httpEntity, int httpStatus, Map
957954
boolean serverCompression = ClientConfigProperties.COMPRESS_SERVER_RESPONSE.getOrDefault(requestConfig);
958955
boolean useHttpCompression = ClientConfigProperties.USE_HTTP_COMPRESSION.getOrDefault(requestConfig);
959956

960-
LOG.debug("wrapResponseEntity: server compression: {}, http compression: {}, content encoding: {}",
961-
serverCompression, useHttpCompression, httpEntity.getContentEncoding());
962-
963957
if (httpEntity.getContentEncoding() != null) {
964958
// http compressed response
965959
return new CompressedEntity(httpEntity, true, CompressorStreamFactory.getSingleton());

‎client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,10 @@
88
import org.testng.Assert;
99
import org.testng.annotations.Test;
1010

11+
import java.io.ByteArrayOutputStream;
12+
import java.io.PrintStream;
1113
import java.util.concurrent.TimeUnit;
14+
import java.util.regex.Pattern;
1215

1316
public class ClientFailoverUnitTest {
1417

@@ -39,4 +42,47 @@ public void testWireMockFailoverOnly() throws Exception {
3942
mockServer.stop();
4043
}
4144
}
45+
46+
@Test
47+
public void testRetryWarnNamesExceptionClass() throws Exception {
48+
ByteArrayOutputStream captured = new ByteArrayOutputStream();
49+
PrintStream originalErr = System.err;
50+
System.setErr(new PrintStream(captured, true, "UTF-8"));
51+
try (Client client = new Client.Builder()
52+
.addEndpoint("http://127.0.0.1:1") // nothing listens here -> connection refused on every attempt
53+
.setUsername("default")
54+
.setPassword("")
55+
.setDefaultDatabase("default")
56+
.setMaxRetries(2)
57+
.build()) {
58+
try {
59+
client.query("SELECT 1").get(30, TimeUnit.SECONDS);
60+
Assert.fail("a query against a dead endpoint should fail after exhausting retries");
61+
} catch (Exception expected) {
62+
// every attempt hits the dead endpoint
63+
}
64+
} finally {
65+
System.err.flush();
66+
System.setErr(originalErr);
67+
}
68+
69+
StringBuilder retryWarns = new StringBuilder();
70+
for (String line : captured.toString("UTF-8").split("\\R")) {
71+
if (line.contains(" WARN ") && line.contains("Retrying.")) {
72+
retryWarns.append(line).append('\n');
73+
}
74+
}
75+
String warn = retryWarns.toString();
76+
Assert.assertFalse(warn.isEmpty(),
77+
"expected a consolidated retry WARN to be emitted:\n" + captured.toString("UTF-8"));
78+
// The cause must name the exception class (informative even when getMessage() is null),
79+
// not just its message.
80+
Assert.assertTrue(Pattern.compile("cause: [\\w$.]+(Exception|Error):").matcher(warn).find(),
81+
"retry WARN should name the exception class in the cause, was:\n" + warn);
82+
// The attempt counter is 1-based and the total counts the initial try plus the retries; the
83+
// "+1" is applied inside logRetryAndSelectNextNode, so with maxRetries=2 the first retry WARN
84+
// reads "attempt 1 of 3".
85+
Assert.assertTrue(warn.contains("attempt 1 of 3"),
86+
"retry WARN should report the 1-based attempt and total-attempt count, was:\n" + warn);
87+
}
4288
}

‎jdbc-v2/src/main/java/com/clickhouse/jdbc/ConnectionImpl.java‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -96,9 +96,7 @@ public ConnectionImpl(String url, Properties info) throws SQLException {
9696
clientName = this.appName + " " + clientName; // Use the application name as client name
9797
}
9898

99-
if (this.config.isDisableFrameworkDetection()) {
100-
LOG.debug("Framework detection is disabled.");
101-
} else {
99+
if (!this.config.isDisableFrameworkDetection()) {
102100
String detectedFrameworks = Driver.FrameworksDetection.getFrameworksDetected();
103101
LOG.debug("Detected frameworks: {}", detectedFrameworks);
104102
if (!detectedFrameworks.trim().isEmpty()) {

‎jdbc-v2/src/main/java/com/clickhouse/jdbc/Driver.java‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -62,10 +62,7 @@ public static String getFrameworksDetected() {
6262
public static final String DRIVER_CLIENT_NAME = "jdbc-v2/";
6363

6464
static {
65-
log.debug("Initializing ClickHouse JDBC driver V2");
66-
6765
driverVersion = ClickHouseClientOption.readVersionFromResource("jdbc-v2-version.properties");
68-
log.debug("ClickHouse JDBC driver version: {}", driverVersion);
6966

7067
int[] versions = parseVersion(driverVersion);
7168

‎jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -750,8 +750,6 @@ private String encodeObject(Object x) throws SQLException {
750750
private static final char C_BRACKET = ']';
751751

752752
private String encodeObject(Object x, Long length) throws SQLException {
753-
LOG.trace("Encoding object: {}", x);
754-
755753
try {
756754
if (x == null) {
757755
return "NULL";

‎jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -78,11 +78,9 @@ protected void ensureOpen() throws SQLException {
7878
}
7979

8080
private String parseJdbcEscapeSyntax(String sql) {
81-
LOG.trace("Original SQL: {}", sql);
8281
if (escapeProcessingEnabled) {
8382
sql = escapedSQLToNative(sql);
8483
}
85-
LOG.trace("Escaped SQL: {}", sql);
8684
return sql;
8785
}
8886

0 commit comments

Comments
 (0)