From d13beae7ce9ead8fb37e6e088bbf2363ef2c4fb7 Mon Sep 17 00:00:00 2001 From: LjungeldTheHelper <352537209+LjungeldTheHelper@users.noreply.github.com> Date: Wed, 4 Nov 2026 17:13:23 -0800 Subject: [PATCH] Remove sensitive and repetitive logging in client-v2 and jdbc-v2 (#3295) Logs of client-v2 and jdbc-v2 no longer carry SQL, bound values, credentials, query IDs, client metadata, endpoint addresses or exception messages at any level, and no longer repeat per retry, request stream, statement or metadata object. - client-v2: one WARN per operation that recovers after retries instead of one per attempt plus one before the throw; endpoint quarantine and the all-endpoints-down fallback logged once; transport log-and-rethrow removed; User-Agent warning reports the length only; per-stream compressor DEBUG removed; swallowed failures logged by type. - jdbc-v2: SQL TRACE and JavaCC DEBUG of the SQL and parser error removed; per-statement query ID, metadata argument and per-object logs removed or aggregated; log-and-throw duplicates removed. - Tests: canaries at TRACE for both modules, retry log volume. Co-Authored-By: Claude Opus 5.5 --- .../com/clickhouse/client/api/Client.java | 37 +++--- .../internal/BinaryStreamReader.java | 1 - .../data_formats/internal/ProcessParser.java | 2 +- .../client/api/internal/ClientUtils.java | 24 +++- .../internal/CompressedBlockInputStream.java | 5 - .../internal/CompressedBlockOutputStream.java | 4 - .../client/api/internal/EnvUtils.java | 2 +- .../api/internal/HttpAPIClientHelper.java | 41 +++---- .../api/internal/WorkloadIdentitySupport.java | 5 +- .../client/api/serde/POJOSerDe.java | 4 +- .../api/transport/ClientNodeSelector.java | 17 ++- .../client/api/transport/EndpointState.java | 12 +- .../client/api/ClientFailoverUnitTest.java | 95 ++++++++++----- .../client/api/internal/ClientUtilsTest.java | 19 ++- .../api/internal/HttpAPIClientHelperTest.java | 88 +++++++++++--- docs/features.md | 2 + history/latest/3295.md | 11 ++ .../jdbc/PreparedStatementImpl.java | 8 +- .../com/clickhouse/jdbc/ResultSetImpl.java | 5 - .../com/clickhouse/jdbc/StatementImpl.java | 25 ++-- .../jdbc/internal/SqlParserFacade.java | 6 +- .../jdbc/metadata/DatabaseMetaDataImpl.java | 8 -- .../jdbc/metadata/ShowStatementsMetaData.java | 21 +++- .../src/main/javacc/ClickHouseSqlParser.jj | 5 +- .../jdbc/JDBCErrorHandlingTests.java | 10 +- .../com/clickhouse/jdbc/LoggingTestUtils.java | 55 +++++++++ .../clickhouse/jdbc/StatementLoggingTest.java | 110 ++++++++++++++++++ .../ClickHouseSqlParserLoggingTest.java | 49 +++----- .../jdbc/metadata/DatabaseMetaDataTest.java | 77 ++++-------- 29 files changed, 506 insertions(+), 242 deletions(-) create mode 100644 history/latest/3295.md create mode 100644 jdbc-v2/src/test/java/com/clickhouse/jdbc/LoggingTestUtils.java create mode 100644 jdbc-v2/src/test/java/com/clickhouse/jdbc/StatementLoggingTest.java diff --git a/client-v2/src/main/java/com/clickhouse/client/api/Client.java b/client-v2/src/main/java/com/clickhouse/client/api/Client.java index 0d843d3c0a..2257916844 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/Client.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/Client.java @@ -221,7 +221,6 @@ private Client(Collection endpoints, Map configuration, if (httpEndpoint.isSecure()) { initSslContext = true; } - LOG.debug("Adding endpoint: {}", httpEndpoint); tmpEndpoints.add(httpEndpoint); } else { throw new ClientException("Unsupported endpoint type: " + ep.getClass().getName()); @@ -290,7 +289,7 @@ public void close() { this.sharedOperationExecutor.shutdownNow(); } } catch (Exception e) { - LOG.error("Failed to close shared operation executor", e); + LOG.warn("Failed to close shared operation executor", e); } } else { LOG.debug("Skip closing operation executor because not owned by client"); @@ -1498,7 +1497,9 @@ public boolean ping(long timeout) { return true; } } catch (Exception e) { - LOG.debug("Failed to connect to the server (Duration: {})", durationSince(startTime), e); + // The exception message can carry the endpoint or a server message: log only its type. + LOG.debug("Ping failed after {} ms: {}", durationSince(startTime).toMillis(), + ClientUtils.rootCauseClassName(e)); return false; } } @@ -1658,6 +1659,7 @@ public CompletableFuture insert(String tableName, List data, spanRecorder.recordInsertSuccess(operationSpan, metrics); metricsRecorder.recordInsertSuccess(requestSettings, tableName, metrics); + logRecoveredRetries("Insert", i, lastException); return new InsertResponse(transportResponse, metrics); } catch (Exception e) { String msg = requestExMsg("Insert", (i + 1), durationSince(startTime).toMillis(), requestSettings.getQueryId()); @@ -1665,7 +1667,7 @@ public CompletableFuture insert(String tableName, List data, if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(queryId)) { if (i < maxAttempts) { metricsRecorder.recordInsertRetry(requestSettings, tableName, lastException); - selectedEndpoint = logRetryAndSelectNextNode("Insert", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e); + selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint); } else { nodeSelector.getNextAliveNode(selectedEndpoint); } @@ -1676,7 +1678,6 @@ public CompletableFuture insert(String tableName, List data, } String errMsg = requestExMsg("Insert", maxAttempts + 1, durationSince(startTime).toMillis(), requestSettings.getQueryId()); - LOG.warn(errMsg); throw (lastException == null ? new ClientException(errMsg) : lastException); } catch (RuntimeException | Error e) { // Taken before any recorder runs, like the duration of a successful operation, which the @@ -1884,6 +1885,7 @@ public CompletableFuture insert(String tableName, requestSettings.getQueryId(), OperationType.INSERT); spanRecorder.recordInsertSuccess(operationSpan, metrics); metricsRecorder.recordInsertSuccess(requestSettings, tableName, metrics); + logRecoveredRetries("Insert", i, lastException); return new InsertResponse(transportResponse, metrics); } catch (Exception e) { String msg = requestExMsg("Insert", (i + 1), durationSince(startTime).toMillis(), requestSettings.getQueryId()); @@ -1891,7 +1893,7 @@ public CompletableFuture insert(String tableName, if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(requestSettings.getQueryId())) { if (i < maxAttempts) { metricsRecorder.recordInsertRetry(requestSettings, tableName, lastException); - selectedEndpoint = logRetryAndSelectNextNode("Insert (stream)", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e); + selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint); } else { nodeSelector.getNextAliveNode(selectedEndpoint); } @@ -1910,7 +1912,6 @@ public CompletableFuture insert(String tableName, } String errMsg = requestExMsg("Insert", maxAttempts + 1, durationSince(startTime).toMillis(), requestSettings.getQueryId()); - LOG.warn(errMsg); throw (lastException == null ? new ClientException(errMsg) : lastException); } catch (RuntimeException | Error e) { // Taken before any recorder runs, like the duration of a successful operation, which the @@ -2042,6 +2043,7 @@ public CompletableFuture query(String sqlQuery, Map query(String sqlQuery, Map query(String sqlQuery, Map query(String sqlQuery, Map 0 && LOG.isWarnEnabled()) { + LOG.warn("{} succeeded after {} {}; last retried failure: {}", operation, retries, + retries == 1 ? "retry" : "retries", ClientUtils.rootCauseClassName(lastFailure)); + } } /** diff --git a/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/BinaryStreamReader.java b/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/BinaryStreamReader.java index 018b0aeb62..53a57fb2f0 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/BinaryStreamReader.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/BinaryStreamReader.java @@ -303,7 +303,6 @@ private T readValue(ClickHouseColumn column, Class typeHint, boolean stri } catch (EOFException e) { throw e; } catch (Exception e) { - log.debug("Failed to read value for column {}, {}", column.getColumnName(), e.getLocalizedMessage()); throw new ClientException("Failed to read value for column " + column.getColumnName(), e); } } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/ProcessParser.java b/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/ProcessParser.java index 8243523032..47bc6fe948 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/ProcessParser.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/data_formats/internal/ProcessParser.java @@ -87,7 +87,7 @@ public static Map parse(String json) { long value = Long.parseLong(valueStr); result.put(key, value); } catch (NumberFormatException e) { - LOG.debug("Skipping summary field '" + key + "' with non-numeric value '" + valueStr + "'", e); + LOG.debug("Skipping summary field '{}' with a non-numeric value", key); } } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/ClientUtils.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/ClientUtils.java index 40314c521a..2a0a8f855f 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/ClientUtils.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/ClientUtils.java @@ -13,6 +13,8 @@ public final class ClientUtils { private static final int DEFAULT_CAUSE_SEARCH_DEPTH = 3; + private static final int ROOT_CAUSE_SEARCH_DEPTH = 16; + private ClientUtils() {} public static boolean isNotBlank(String str) { @@ -28,7 +30,8 @@ public static void quietClose(Closeable closeable, Logger log) { try { closeable.close(); } catch (Exception e) { - log.warn("Failed to close object " + closeable, e); + // The type, not toString(): a closeable can describe a request or a response. + log.debug("Failed to close object of type {}", closeable.getClass().getName(), e); } } } @@ -94,4 +97,23 @@ public static T findCause(Throwable throwable, Class ty } return null; } + + /** + * Returns the class name of the deepest cause of {@code throwable}, following up to 16 causes. Use it to log a + * failure without its message: a message can carry SQL, values, endpoints or a server response. + * + * @param throwable - exception to start from, can be {@code null} + * @return class name of the deepest cause, or {@code "none"} if {@code throwable} is {@code null} + */ + public static String rootCauseClassName(Throwable throwable) { + if (throwable == null) { + return "none"; + } + Throwable current = throwable; + for (int depth = 0; depth < ROOT_CAUSE_SEARCH_DEPTH && current.getCause() != null + && current.getCause() != current; depth++) { + current = current.getCause(); + } + return current.getClass().getName(); + } } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockInputStream.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockInputStream.java index 5f749fb641..ff9677d378 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockInputStream.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockInputStream.java @@ -6,8 +6,6 @@ import com.clickhouse.data.ClickHouseUtils; import com.github.luben.zstd.Zstd; import net.jpountz.lz4.LZ4FastDecompressor; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.io.EOFException; import java.io.IOException; @@ -16,7 +14,6 @@ public class CompressedBlockInputStream extends InputStream { - private static final Logger LOG = LoggerFactory.getLogger(CompressedBlockInputStream.class); private final LZ4FastDecompressor decompressor; private final InputStream in; @@ -25,10 +22,8 @@ public class CompressedBlockInputStream extends InputStream { private final byte[] tmpBuffer = new byte[1]; - public CompressedBlockInputStream(InputStream in, LZ4FastDecompressor decompressor, int bufferSize) { super(); - LOG.debug("Using decompressor with buffer size {}", bufferSize); this.decompressor = decompressor; this.in = in; this.buffer = ByteBuffer.allocate(bufferSize); diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockOutputStream.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockOutputStream.java index 750bdf80ca..cf25ea7ab2 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockOutputStream.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/CompressedBlockOutputStream.java @@ -3,8 +3,6 @@ import com.clickhouse.data.ClickHouseCityHash; import com.github.luben.zstd.Zstd; import net.jpountz.lz4.LZ4Compressor; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.io.IOException; import java.io.OutputStream; @@ -12,7 +10,6 @@ public abstract class CompressedBlockOutputStream extends OutputStream { - private static final Logger LOG = LoggerFactory.getLogger(CompressedBlockOutputStream.class); public static final int UNCOMPRESSED_BUFF_SIZE = 64 * 1024; // 64K is most optimal for LZ4 compression private final ByteBuffer inBuffer; @@ -23,7 +20,6 @@ public abstract class CompressedBlockOutputStream extends OutputStream { public CompressedBlockOutputStream(OutputStream out, int bufferSize) { super(); - LOG.debug("Using compressor with buffer size {}", bufferSize); this.inBuffer = ByteBuffer.allocate(bufferSize); this.out = out; this.compressedBuffer = ByteBuffer.allocate(bufferSize + CompressedBlockInputStream.HEADER_LENGTH); diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/EnvUtils.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/EnvUtils.java index 91caedcdbd..d514fba7b5 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/EnvUtils.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/EnvUtils.java @@ -36,7 +36,7 @@ public static String getLocalhostNameOrAddress(final boolean returnAddress) { } } } catch (Exception e) { - LOG.error("Failed to get local host name or address", e); + LOG.warn("Failed to get local host name or address: {}", ClientUtils.rootCauseClassName(e)); } return ""; } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java index 07f8e4f542..e5c66b933b 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java @@ -306,7 +306,7 @@ private HttpClientConnectionManager poolConnectionManager(LayeredConnectionSocke applyMethod = micrometerLoader.getDeclaredMethod("applyConnectionMetricsBinder", Object.class, String.class, MeteredManagedHttpClientConnectionFactory.class); applyMethod.invoke(micrometerLoader, metricsRegistry, mGroupName, connectionFactory); } catch (Exception e) { - LOG.error("Failed to register metrics", e); + LOG.warn("Failed to register connection pool metrics", e); } } return phccm; @@ -435,7 +435,9 @@ public Exception readError(HttpPost req, ClassicHttpResponse httpResponse) { return serverCode > 0 ? readClickHouseError(httpResponse.getEntity(), serverCode, queryId, httpResponse.getCode()) : readNotClickHouseError(httpResponse.getEntity(), queryId, httpResponse.getCode()); } catch (Exception e) { - LOG.error("Failed to read error message", e); + // Only the type: the message of a failure to read the body can echo the body. + LOG.warn("Failed to read the server error message (HTTP status {}, server error code {}): {}", + httpResponse.getCode(), serverCode, ClientUtils.rootCauseClassName(e)); String msg = String.format(ERROR_CODE_PREFIX_PATTERN, serverCode) + " (transport error: " + httpResponse.getCode() + ")"; return new ServerException(serverCode, msg + " (queryId= " + queryId + ")", httpResponse.getCode(), queryId); } @@ -473,7 +475,8 @@ private ServerException readNotClickHouseError(HttpEntity httpEntity, String que } throw e; } catch (Exception e) { - LOG.warn("Failed to read error message (queryId = " + queryId + ")", e); + LOG.warn("Failed to read the server error message (HTTP status {}): {}", httpCode, + ClientUtils.rootCauseClassName(e)); break; } } @@ -716,14 +719,14 @@ public void close() throws IOException { if (!dataStreamCreated) { throw e; } - logIncompleteBodyOnClose(getQueryId(), e); + logIncompleteBodyOnClose(e); } } @Override public InputStream createDataInputStream() { try { - InputStream stream = new ResponseBodyInputStream(delegate.getEntity().getContent(), getQueryId()); + InputStream stream = new ResponseBodyInputStream(delegate.getEntity().getContent()); dataStreamCreated = true; return stream; } catch (Exception e) { @@ -739,11 +742,8 @@ public InputStream createDataInputStream() { */ private static final class ResponseBodyInputStream extends FilterInputStream { - private final String queryId; - - ResponseBodyInputStream(InputStream in, String queryId) { + ResponseBodyInputStream(InputStream in) { super(in); - this.queryId = queryId; } @Override @@ -751,13 +751,13 @@ public void close() throws IOException { try { super.close(); } catch (ConnectionClosedException e) { - logIncompleteBodyOnClose(queryId, e); + logIncompleteBodyOnClose(e); } } } - private static void logIncompleteBodyOnClose(String queryId, ConnectionClosedException e) { - LOG.debug("Ignoring incomplete response body on close (queryId = {})", queryId, e); + private static void logIncompleteBodyOnClose(ConnectionClosedException e) { + LOG.debug("Ignoring incomplete response body on close", e); } /** @@ -868,14 +868,8 @@ private TransportResponse doExecuteRequest(TransportRequest transportRequest, Sp logServerErrorResponse(req, httpResponse); throw new ClientException("Unexpected result status " + statusCode); } - } catch (UnknownHostException e) { - LOG.debug("Host '{}' unknown", req.getAuthority()); - throw e; - } catch (ConnectException | NoRouteToHostException e) { - LOG.debug("Failed to connect to '{}': {}", req.getAuthority(), e.getMessage()); - throw e; } catch (Exception e) { - LOG.debug("Failed to execute request to '{}': {}", req.getAuthority(), e.getMessage(), e); + // Not logged: the exception is propagated to the caller. if (e instanceof RequestFailedException && req.isCancelled()) { throw new TransportException("Request was cancelled on client side", e, getQueryId(httpResponse, req)); } @@ -910,8 +904,9 @@ private String getQueryId(HttpResponse httpResponse, HttpPost httpRequest) { } /** - * Logs a server error response at WARN (status, query id, authority, exception-code header). The body is - * not logged: {@link #readError} consumes it and it may contain SQL/data. + * Logs a server error response at WARN (status, exception-code header). The body is not logged: + * {@link #readError} consumes it and it may contain SQL/data. The query ID and the authority are not logged + * either: the query ID can be supplied by the application and the authority names the server. */ private void logServerErrorResponse(HttpPost req, ClassicHttpResponse httpResponse) { // Null-safe: the error path must never let its own logger throw and mask the real failure. @@ -919,10 +914,8 @@ private void logServerErrorResponse(HttpPost req, ClassicHttpResponse httpRespon return; } final Header exceptionCodeHeader = httpResponse.getFirstHeader(ClickHouseHttpProto.HEADER_EXCEPTION_CODE); - LOG.warn("Server returned error response: status={}, queryId='{}', authority='{}', {}={}", + LOG.warn("Server returned error response: status={}, {}={}", httpResponse.getCode(), - getQueryId(httpResponse, req), - req.getAuthority(), ClickHouseHttpProto.HEADER_EXCEPTION_CODE, exceptionCodeHeader == null ? "" : exceptionCodeHeader.getValue()); } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/internal/WorkloadIdentitySupport.java b/client-v2/src/main/java/com/clickhouse/client/api/internal/WorkloadIdentitySupport.java index 29106c527a..a4a7d5e36c 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/internal/WorkloadIdentitySupport.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/internal/WorkloadIdentitySupport.java @@ -80,8 +80,9 @@ public synchronized void updateClientName(Map configuration) { (String) configuration.get(ClientConfigProperties.httpHeader(HttpHeaders.USER_AGENT)), configuration); String userAgent = composeUserAgent(application); if (userAgent.length() > USER_AGENT_WARNING_LENGTH) { - LOG.warn("The User-Agent value is {} characters long, more than {}: '{}'. Use a shorter client name or" - + " less client metadata.", userAgent.length(), USER_AGENT_WARNING_LENGTH, userAgent); + // The value itself is not logged: it holds the client name and metadata the application supplied. + LOG.warn("The User-Agent value is {} characters long, more than {}. Use a shorter client name or" + + " less client metadata.", userAgent.length(), USER_AGENT_WARNING_LENGTH); } // the value is written first, so a request that reads the new application part also reads the new value this.clientUserAgent = userAgent; diff --git a/client-v2/src/main/java/com/clickhouse/client/api/serde/POJOSerDe.java b/client-v2/src/main/java/com/clickhouse/client/api/serde/POJOSerDe.java index a454f0a53e..d12b97acf3 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/serde/POJOSerDe.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/serde/POJOSerDe.java @@ -67,7 +67,7 @@ public void registerClass(Class clazz, TableSchema schema) { } }); } else { - LOG.warn("No getter method found for column: {}", propertyName); + LOG.debug("No getter method found for column: {}", propertyName); } // Deserialization stuff @@ -75,7 +75,7 @@ public void registerClass(Class clazz, TableSchema schema) { if (setterMethod != null) { schemaDeserializers.put(column.getColumnName(), SerializerUtils.compilePOJOSetter(setterMethod, column)); } else { - LOG.warn("No setter method found for column: {}", propertyName); + LOG.debug("No setter method found for column: {}", propertyName); } } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/transport/ClientNodeSelector.java b/client-v2/src/main/java/com/clickhouse/client/api/transport/ClientNodeSelector.java index 1fefff8f27..5305baf927 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/transport/ClientNodeSelector.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/transport/ClientNodeSelector.java @@ -6,6 +6,7 @@ import java.util.ArrayList; import java.util.Collections; import java.util.List; +import java.util.concurrent.atomic.AtomicBoolean; /** * So we will look up for the first-alive node and then assign that node to @@ -33,6 +34,9 @@ public class ClientNodeSelector { private final List endpointStates; + /** Set while all endpoints are quarantined, so that the fallback is logged once per outage, not per request. */ + private final AtomicBoolean allEndpointsDownLogged = new AtomicBoolean(); + public ClientNodeSelector(List endpoints) { List states = new ArrayList<>(endpoints.size()); for (Endpoint ep : endpoints) { @@ -44,18 +48,25 @@ public ClientNodeSelector(List endpoints) { public Endpoint getEndpoint() { for (EndpointState state : endpointStates) { if (state.isAlive()) { + if (allEndpointsDownLogged.get()) { + allEndpointsDownLogged.set(false); + } return state.getEndpoint(); } } - LOG.warn("All endpoints are non-responsive, falling back to primary endpoint"); + if (allEndpointsDownLogged.compareAndSet(false, true)) { + LOG.warn("All endpoints are non-responsive, falling back to primary endpoint"); + } return endpointStates.get(0).getEndpoint(); } public Endpoint getNextAliveNode(Endpoint failedEndpoint) { for (EndpointState state : endpointStates) { if (state.getEndpoint().equals(failedEndpoint)) { - state.markFailed(DEFAULT_QUARANTINE_MS); - LOG.warn("Endpoint {} quarantined for {} ms", failedEndpoint.getHost(), DEFAULT_QUARANTINE_MS); + // A failure of an endpoint that is quarantined already only extends the quarantine. + if (state.markFailed(DEFAULT_QUARANTINE_MS)) { + LOG.warn("Endpoint {} quarantined for {} ms", failedEndpoint.getHost(), DEFAULT_QUARANTINE_MS); + } break; } } diff --git a/client-v2/src/main/java/com/clickhouse/client/api/transport/EndpointState.java b/client-v2/src/main/java/com/clickhouse/client/api/transport/EndpointState.java index 4671400be1..a70e5156e6 100644 --- a/client-v2/src/main/java/com/clickhouse/client/api/transport/EndpointState.java +++ b/client-v2/src/main/java/com/clickhouse/client/api/transport/EndpointState.java @@ -20,11 +20,19 @@ Endpoint getEndpoint() { return endpoint; } - void markFailed(long quarantineMs) { + /** + * Quarantines the endpoint, or extends its quarantine. + * + * @return {@code true} if the endpoint was alive before this call + */ + boolean markFailed(long quarantineMs) { if (quarantineMs <= 0) { throw new IllegalArgumentException("Quarantine duration must be positive: " + quarantineMs); } - this.failedUntil = System.currentTimeMillis() + quarantineMs; + long now = System.currentTimeMillis(); + boolean wasAlive = now >= failedUntil; + this.failedUntil = now + quarantineMs; + return wasAlive; } boolean isAlive() { diff --git a/client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java b/client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java index fec82a0285..7c5cd9a3da 100644 --- a/client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java +++ b/client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java @@ -2,14 +2,18 @@ import com.clickhouse.client.api.Client; import com.clickhouse.client.api.query.QueryResponse; +import com.clickhouse.client.api.query.QuerySettings; import com.github.tomakehurst.wiremock.WireMockServer; import com.github.tomakehurst.wiremock.client.WireMock; import com.github.tomakehurst.wiremock.core.WireMockConfiguration; import org.testng.Assert; +import org.testng.annotations.DataProvider; import org.testng.annotations.Test; import java.io.ByteArrayOutputStream; import java.io.PrintStream; +import java.util.ArrayList; +import java.util.List; import java.util.concurrent.TimeUnit; import java.util.regex.Pattern; @@ -43,46 +47,77 @@ public void testWireMockFailoverOnly() throws Exception { } } - @Test - public void testRetryWarnNamesExceptionClass() throws Exception { + @DataProvider(name = "retryLogging") + public static Object[][] retryLogging() { + return new Object[][] { + // healthy endpoint after the dead one, maxRetries + {true, 3}, + {false, 2}, + }; + } + + /** + * A retried query logs no WARN per attempt: a query that recovers logs one summary naming the type of the + * last failure, and a query that fails after all attempts logs nothing beyond the bounded endpoint state + * changes, because its exception reaches the caller. Neither logs the endpoint address or the query ID. + */ + @Test(dataProvider = "retryLogging") + public void testRetryLoggedOncePerOperation(boolean recovers, int maxRetries) throws Exception { + String queryId = "retry-log-query-id-" + System.nanoTime(); + WireMockServer mockServer = new WireMockServer(WireMockConfiguration.options().dynamicPort()); + mockServer.start(); ByteArrayOutputStream captured = new ByteArrayOutputStream(); PrintStream originalErr = System.err; System.setErr(new PrintStream(captured, true, "UTF-8")); - try (Client client = new Client.Builder() - .addEndpoint("http://127.0.0.1:1") // nothing listens here -> connection refused on every attempt - .setUsername("default") - .setPassword("") - .setDefaultDatabase("default") - .setMaxRetries(2) - .build()) { - try { - client.query("SELECT 1").get(30, TimeUnit.SECONDS); - Assert.fail("a query against a dead endpoint should fail after exhausting retries"); - } catch (Exception expected) { - // every attempt hits the dead endpoint + try { + mockServer.stubFor(WireMock.post(WireMock.anyUrl()) + .willReturn(WireMock.aResponse().withStatus(200).withBody(""))); + Client.Builder builder = new Client.Builder() + .addEndpoint("http://127.0.0.1:1") // nothing listens here -> connection refused + .setUsername("default") + .setPassword("") + .setDefaultDatabase("default") + .setMaxRetries(maxRetries); + if (recovers) { + builder.addEndpoint("http://localhost:" + mockServer.port()); + } + try (Client client = builder.build()) { + client.query("SELECT 1", new QuerySettings().setQueryId(queryId)).get(30, TimeUnit.SECONDS).close(); + Assert.assertTrue(recovers, "a query against a dead endpoint must fail after exhausting retries"); + } catch (Exception e) { + Assert.assertFalse(recovers, "the query must recover on the healthy endpoint: " + e); } } finally { System.err.flush(); System.setErr(originalErr); + mockServer.stop(); } - StringBuilder retryWarns = new StringBuilder(); - for (String line : captured.toString("UTF-8").split("\\R")) { - if (line.contains(" WARN ") && line.contains("Retrying.")) { - retryWarns.append(line).append('\n'); + String logged = captured.toString("UTF-8"); + List warns = new ArrayList<>(); + for (String line : logged.split("\\R")) { + if (line.contains(" WARN ")) { + warns.add(line); } } - String warn = retryWarns.toString(); - Assert.assertFalse(warn.isEmpty(), - "expected a consolidated retry WARN to be emitted:\n" + captured.toString("UTF-8")); - // The cause must name the exception class (informative even when getMessage() is null), - // not just its message. - Assert.assertTrue(Pattern.compile("cause: [\\w$.]+(Exception|Error):").matcher(warn).find(), - "retry WARN should name the exception class in the cause, was:\n" + warn); - // The attempt counter is 1-based and the total counts the initial try plus the retries; the - // "+1" is applied inside logRetryAndSelectNextNode, so with maxRetries=2 the first retry WARN - // reads "attempt 1 of 3". - Assert.assertTrue(warn.contains("attempt 1 of 3"), - "retry WARN should report the 1-based attempt and total-attempt count, was:\n" + warn); + List summaries = new ArrayList<>(); + int quarantines = 0; + for (String warn : warns) { + if (warn.contains("succeeded after")) { + summaries.add(warn); + } else if (warn.contains("quarantined")) { + quarantines++; + } + } + Assert.assertEquals(summaries.size(), recovers ? 1 : 0, "retry summaries:\n" + logged); + if (recovers) { + Assert.assertTrue(Pattern.compile("Query succeeded after 1 retry; last retried failure: [\\w$.]+(Exception|Error)") + .matcher(summaries.get(0)).find(), "the summary must name the failure type: " + summaries.get(0)); + } + Assert.assertEquals(quarantines, 1, "the dead endpoint must be reported once per quarantine:\n" + logged); + Assert.assertTrue(warns.size() <= 3, "a retried query must not log a WARN per attempt:\n" + logged); + Assert.assertFalse(logged.contains("Retrying"), "per-attempt retry messages must not be logged:\n" + logged); + Assert.assertFalse(logged.contains(queryId), "the query ID must not be logged:\n" + logged); + Assert.assertFalse(logged.contains("127.0.0.1:1"), "the endpoint address must not be logged:\n" + logged); } } diff --git a/client-v2/src/test/java/com/clickhouse/client/api/internal/ClientUtilsTest.java b/client-v2/src/test/java/com/clickhouse/client/api/internal/ClientUtilsTest.java index d26c75e825..74bc4cab60 100644 --- a/client-v2/src/test/java/com/clickhouse/client/api/internal/ClientUtilsTest.java +++ b/client-v2/src/test/java/com/clickhouse/client/api/internal/ClientUtilsTest.java @@ -25,7 +25,9 @@ public void testQuietCloseSwallowsExceptionAndLogs() throws IOException { ClientUtils.quietClose(closeable, log); Mockito.verify(closeable).close(); - Mockito.verify(log).warn(Mockito.contains("Failed to close object"), Mockito.eq(failure)); + Mockito.verify(log).debug(Mockito.contains("Failed to close object"), Mockito.eq(closeable.getClass().getName()), + Mockito.eq(failure)); + Mockito.verifyNoMoreInteractions(log); } @Test(groups = {"unit"}) @@ -50,6 +52,21 @@ public void testQuietCloseWithNull() { Assert.assertTrue(true); } + @DataProvider(name = "rootCauseClassName") + public static Object[][] rootCauseClassName() { + IOException root = new IOException("secret"); + return new Object[][] { + {null, "none"}, + {root, IOException.class.getName()}, + {new RuntimeException("outer", new IllegalStateException("middle", root)), IOException.class.getName()}, + }; + } + + @Test(groups = {"unit"}, dataProvider = "rootCauseClassName") + public void testRootCauseClassName(Throwable throwable, String expected) { + Assert.assertEquals(ClientUtils.rootCauseClassName(throwable), expected); + } + @Test(groups = {"unit"}, dataProvider = "putIfAbsentIgnoreCase") public void testPutIfAbsentIgnoreCase(String[] existingKeys, String key, String expectedMap) { Map map = new LinkedHashMap<>(); diff --git a/client-v2/src/test/java/com/clickhouse/client/api/internal/HttpAPIClientHelperTest.java b/client-v2/src/test/java/com/clickhouse/client/api/internal/HttpAPIClientHelperTest.java index fd3dfb0004..7dc693e241 100644 --- a/client-v2/src/test/java/com/clickhouse/client/api/internal/HttpAPIClientHelperTest.java +++ b/client-v2/src/test/java/com/clickhouse/client/api/internal/HttpAPIClientHelperTest.java @@ -4,6 +4,7 @@ import com.clickhouse.client.api.ClientConfigProperties; import com.clickhouse.client.api.ClientFaultCause; import com.clickhouse.client.api.ServerException; +import com.clickhouse.client.api.command.CommandSettings; import com.clickhouse.client.api.enums.SSLMode; import com.clickhouse.client.api.http.ClickHouseHttpProto; import com.clickhouse.client.api.internal.HttpAPIClientHelper.CustomSSLConnectionFactory; @@ -57,6 +58,7 @@ import java.util.HashMap; import java.util.List; import java.util.Map; +import java.util.concurrent.ExecutionException; import java.util.concurrent.TimeUnit; import static org.mockito.ArgumentMatchers.any; @@ -545,8 +547,8 @@ public void testUserAgentKeptAfterClientNameUpdate() throws Exception { } /** - * A {@code User-Agent} value of the client configuration that is longer than 200 characters is logged as a - * warning, when the client is created and when the client name changes. A value composed for one request is not + * A {@code User-Agent} value of the client configuration that is longer than 200 characters is reported by its + * length, without the value, as a warning when the client is created and when the client name changes. A value composed for one request is not * logged, so that the log does not repeat for every request. */ @Test @@ -556,8 +558,9 @@ public void testLongUserAgentLoggedAsWarning() throws Exception { String warning = "The User-Agent value is "; assertFalse(captureStdErr(() -> newClient(atLimit).close()).contains(warning)); - assertTrue(captureStdErr(() -> newClient(overLimit).close()) - .contains(warning + "201 characters long, more than 200")); + String logged = captureStdErr(() -> newClient(overLimit).close()); + assertTrue(logged.contains(warning + "201 characters long, more than 200."), logged); + assertFalse(logged.contains(overLimit), "the User-Agent value must not be logged: " + logged); try (Client client = newClient("my-app/1.0")) { HttpAPIClientHelper helper = helperOf(client); @@ -641,11 +644,12 @@ public void testServerErrorLoggedOnlyForUnknownStatus(int statusCode, String exc assertTrue(logged.contains("Server returned error response"), "an unknown status code must be logged at WARN: " + logged); assertTrue(logged.contains(String.valueOf(statusCode)), "the HTTP status code must be logged: " + logged); - assertTrue(logged.contains("qid-log-test"), "the query id must be logged: " + logged); } else { assertFalse(logged.contains("Server returned error response"), "status " + statusCode + " must not emit a server-error WARN: " + logged); } + assertFalse(logged.contains("qid-log-test"), "the query id must not be logged: " + logged); + assertFalse(logged.contains("localhost:8123"), "the authority must not be logged: " + logged); } /** @@ -686,32 +690,68 @@ public void testLogServerErrorResponseIsNullSafeAndLogsExceptionCode() throws Ex private static final String CANARY_HEADER_VALUE = "canary-header-5b1d"; private static final String CANARY_SQL = "SELECT 'canary-sql-8d4f'"; private static final String CANARY_RESPONSE = "canary-response-1e6c"; + private static final String CANARY_ERROR = "canary-error-6f0a"; + private static final String CANARY_QUERY_ID = "canary-query-id-3a7e"; + private static final String CANARY_URL_VALUE = "canary-url-value-4d8f"; + private static final String CANARY_APP = "canary-app-9c2b"; + private static final String CANARY_METADATA = "canary-metadata-0b5e"; + private static final String DEAD_ENDPOINT = "http://127.0.0.1:1"; + /** Every logger of client-v2. slf4j-simple caches loggers by name, so a level set here is the level they use. */ + private static final List CLIENT_LOGGERS = Arrays.asList( + "com.clickhouse.client.api.Client", + "com.clickhouse.client.api.ClientConfigProperties", + "com.clickhouse.client.api.data_formats.internal.AbstractBinaryFormatReader", + "com.clickhouse.client.api.data_formats.internal.ProcessParser", + "com.clickhouse.client.api.internal.EnvUtils", + "com.clickhouse.client.api.internal.HttpAPIClientHelper", + "com.clickhouse.client.api.internal.WorkloadIdentitySupport", + "com.clickhouse.client.api.serde.POJOSerDe", + "com.clickhouse.client.api.transport.ClientNodeSelector"); @DataProvider(name = "wireLoggingCases") public static Object[][] wireLoggingCases() { return new Object[][] { - // connection pool, HTTPS, authentication - {true, false, "basic"}, - {false, false, "password_header"}, - {true, true, "bearer"}, - {false, true, "basic"}, + // connection pool, HTTPS, authentication, server error response + {true, false, "basic", false}, + {false, false, "password_header", false}, + {true, true, "bearer", false}, + {false, true, "basic", false}, + {true, false, "password_header", true}, + {false, true, "bearer", true}, }; } + /** + * With the Apache HttpClient wire logger at DEBUG and every client logger at TRACE, a request that fails over + * from a dead endpoint and then succeeds or gets a server error logs none of the credentials, headers, SQL, + * bodies, URL values, application metadata or the query ID. (The endpoint address appears in the DEBUG log of + * the Apache HttpClient connection operator, which this test enables, so it is checked by the failover test.) + */ @Test(dataProvider = "wireLoggingCases") - public void testNoWireLoggingWhenWireLoggerIsDebug(boolean connectionPool, boolean secure, String auth) - throws Exception { + public void testNoWireOrSensitiveLoggingAtTrace(boolean connectionPool, boolean secure, String auth, + boolean serverError) throws Exception { WireMockServer server = new WireMockServer(WireMockConfiguration.options().dynamicPort().dynamicHttpsPort() .notifier(new ConsoleNotifier(false))); int wireLevel = setLogLevel(WIRE_LOGGER, LocationAwareLogger.DEBUG_INT); int operatorLevel = setLogLevel(CONNECTION_OPERATOR_LOGGER, LocationAwareLogger.DEBUG_INT); + Map clientLevels = new HashMap<>(); + for (String logger : CLIENT_LOGGERS) { + clientLevels.put(logger, setLogLevel(logger, LocationAwareLogger.TRACE_INT)); + } try { server.start(); - server.stubFor(WireMock.post(WireMock.anyUrl()).willReturn(WireMock.ok(CANARY_RESPONSE))); + server.stubFor(WireMock.post(WireMock.anyUrl()).willReturn(serverError + ? WireMock.aResponse().withStatus(500) + .withHeader(ClickHouseHttpProto.HEADER_EXCEPTION_CODE, "62") + .withBody("Code: 62. DB::Exception: " + CANARY_ERROR + " " + CANARY_SQL) + : WireMock.ok(CANARY_RESPONSE))); Client.Builder builder = new Client.Builder() + .addEndpoint(DEAD_ENDPOINT) .addEndpoint(secure ? "https://localhost:" + server.httpsPort() : "http://localhost:" + server.port()) .enableConnectionPool(connectionPool) .compressServerResponse(false) + .serverSetting("log_comment", CANARY_URL_VALUE) + .setClientName(CANARY_APP, Collections.singletonMap("canary", CANARY_METADATA)) .httpHeader(CANARY_HEADER_NAME, CANARY_HEADER_VALUE); if (secure) { builder.setSSLMode(SSLMode.TRUST); @@ -724,11 +764,18 @@ public void testNoWireLoggingWhenWireLoggerIsDebug(boolean connectionPool, boole } assertTrue(LoggerFactory.getLogger(WIRE_LOGGER).isDebugEnabled()); + assertTrue(LoggerFactory.getLogger(Client.class).isTraceEnabled()); + CommandSettings settings = new CommandSettings(); + settings.setQueryId(CANARY_QUERY_ID); String logged = captureStdErr(() -> { try (Client client = builder.build()) { - client.execute(CANARY_SQL).get(10, TimeUnit.SECONDS).close(); + client.execute(CANARY_SQL, settings).get(10, TimeUnit.SECONDS).close(); + assertFalse(serverError, "a server error must fail the request"); } catch (Exception e) { - throw new RuntimeException(e); + Throwable failure = e instanceof ExecutionException ? e.getCause() : e; + assertTrue(serverError, "the request must succeed: " + failure); + assertTrue(failure.getMessage().contains(CANARY_ERROR), + "the server error must still reach the caller: " + failure); } }); assertTrue(LoggerFactory.getLogger(WIRE_LOGGER).isDebugEnabled(), "the client must not change logger levels"); @@ -747,13 +794,22 @@ public void testNoWireLoggingWhenWireLoggerIsDebug(boolean connectionPool, boole assertTrue(logged.contains(" connected "), "DEBUG logs of other Apache HttpClient loggers must stay: " + logged); + assertTrue(logged.contains("quarantined"), "the client logs must be captured: " + logged); + if (!serverError) { + assertTrue(logged.contains("Query succeeded after 1 retry;"), + "the recovered retry must be logged: " + logged); + } for (String canary : Arrays.asList(CANARY_PASSWORD, CANARY_BASIC, CANARY_TOKEN, CANARY_HEADER_VALUE, - CANARY_SQL, CANARY_RESPONSE)) { + CANARY_SQL, "canary-sql", CANARY_RESPONSE, CANARY_ERROR, CANARY_QUERY_ID, CANARY_URL_VALUE, + CANARY_APP, CANARY_METADATA)) { assertFalse(logged.contains(canary), "'" + canary + "' must not be logged: " + logged); } } finally { setLogLevel(WIRE_LOGGER, wireLevel); setLogLevel(CONNECTION_OPERATOR_LOGGER, operatorLevel); + for (Map.Entry level : clientLevels.entrySet()) { + setLogLevel(level.getKey(), level.getValue()); + } server.stop(); } } diff --git a/docs/features.md b/docs/features.md index 1bd3588ca2..880b57690f 100644 --- a/docs/features.md +++ b/docs/features.md @@ -11,6 +11,7 @@ This document lists stable, user-visible behavior in `client-v2` and `jdbc-v2` t - Custom SSL context: `Client.Builder.setSSLContext(SSLContext)` supplies a fully pre-built `javax.net.ssl.SSLContext`. When set, the client uses it as is instead of building one from the trust/key material (trust store, CA certificate, client certificate/key); those options cannot be combined with a custom context and are rejected as invalid configuration. `ssl_mode` then only controls server hostname verification. This is primarily for material assembled in memory that must never be written to disk. - Authentication modes: Supports username/password credentials, ClickHouse auth headers, bearer tokens, and optional HTTP Basic authentication. - No HTTP wire logging: The connections of the client, with and without the connection pool (`connection_pool_enabled`), never write request or response bytes to the Apache HttpClient wire logger (`org.apache.hc.client5.http.wire`), also when that logger or the root logger is set to `DEBUG`. These bytes contain credentials, SQL, and data. No option turns wire logging on. The client does not change the logging configuration of the application, and the `DEBUG` logs of all other client and Apache HttpClient loggers are not changed: the Apache HttpClient header logger (`org.apache.hc.client5.http.headers`) still writes request headers, including `Authorization`, at `DEBUG`. `jdbc-v2` connections use the same transport. This is a rule for all transports of the client, also for transports that are added in the future (TCP, HTTP, or other): a transport must never write raw request or response bytes to a log. +- No application data in logs: The client never logs SQL, bound values, rows, request or response bodies, credentials, tokens, header values, full URLs or URL query strings, configuration values, the client name or client metadata, query IDs, or exception messages, at any level including `TRACE`; a failure is described by its exception type only. An exception that is thrown to the caller is not logged as well. Retries are not logged per attempt: an operation that succeeds after retries logs one `WARN` with the retry count and the type of the last failure, an endpoint that is quarantined logs one `WARN` with its host name only, and the fallback when all endpoints are quarantined logs one `WARN` until an endpoint is available again. The `User-Agent` length warning reports the length, not the value. No log is written per row, per value, or per request stream. The metrics and spans are not changed and remain the per-attempt record. - Runtime credential updates: Existing `Client` instances can update username/password or bearer-token credentials for subsequent requests without rebuilding the client. - Proxy support: Can send requests through configured HTTP proxies, including proxy credentials. - Connection and socket tuning: Exposes pool sizing, keep-alive, reuse strategy, connect/request/socket timeouts, and low-level socket options. `Client#setNetworkTimeout(int)` (or the `long`/`ChronoUnit` overload) changes the socket-operation timeout for subsequent requests at runtime; requests already created keep their captured value, and an operation-level timeout overrides the client value. The socket buffer options `socket_rcvbuf` and `socket_sndbuf` (`Client.Builder#setSocketRcvbuf`/`#setSocketSndbuf`) have no default value: unless the application sets one, the buffers are left to the operating system, which sizes and auto-tunes them. Setting a fixed size disables that auto-tuning and is capped by the operating system limits, so it is not recommended unless a measurement shows a benefit. @@ -71,6 +72,7 @@ Compatibility-sensitive traits: ## `jdbc-v2` - JDBC driver registration: Registers through the standard JDBC service mechanism and is available through `DriverManager`. +- No application data in logs: The driver never logs SQL statements, bound parameter values, credentials, query IDs, metadata call arguments, or the names of the objects a metadata call reads, at any level including `TRACE`, and neither does the SQL parser when a statement cannot be parsed (it logs one generic `WARN` and falls back as before). An exception that is thrown to the application is not logged as well. A metadata call that skips dropped or unreadable tables or databases logs one `DEBUG` message with their count. Cleanup failures that the driver ignores are logged at `DEBUG` with the exception type only. - JDBC URL parsing: Accepts `jdbc:clickhouse:` and `jdbc:ch:` URLs with host, port, optional HTTP path, optional database, and query parameters. - SSL URL support: Supports HTTPS connections through URL and property configuration, including default protocol and port handling. The `ssl_mode` property selects the verification strictness (`disabled`, `trust`, `verify_ca`, `strict`); values are case-insensitive and the traditional JDBC value `none` is accepted as an alias for `trust`. Root CA and client certificate/key may be supplied as a file path or as inline PEM content. The `ssl_cipher_suites` property (a comma-separated list) restricts the negotiated TLS cipher suites and is forwarded to the underlying `client-v2` transport. - Custom SSL context via properties: A fully pre-built `javax.net.ssl.SSLContext` may be passed as a live object in the connection `Properties` under the `ssl_context` key (added with `Properties.put`, since it is not a string). It is forwarded to the underlying `client-v2` transport and used as is; trust/key material properties (e.g. `sslrootcert`, `sslcert`) cannot be combined with it and are rejected, while `ssl_mode` then only controls hostname verification. This supports diskless, in-memory TLS material behind connection pools that only expose `java.util.Properties`. diff --git a/history/latest/3295.md b/history/latest/3295.md new file mode 100644 index 0000000000..22e0bdd215 --- /dev/null +++ b/history/latest/3295.md @@ -0,0 +1,11 @@ +- **[client-v2, jdbc-v2]** Logs no longer carry application data and no longer repeat. The client and the JDBC + driver do not log SQL, bound values, credentials, query IDs, the client name and metadata, endpoint addresses (an + endpoint quarantine names the host only) or exception messages at any level, `TRACE` included: the JDBC statement `TRACE` of the SQL, the SQL parser `DEBUG` of + a statement that cannot be parsed, the `User-Agent` warning (now only its length) and the transport `DEBUG` of + failed requests exposed them. A retried operation no longer logs a `WARN` per attempt and another before its + exception is thrown: an operation that recovers logs one `WARN` with the retry count and the type of the last failure, + and an endpoint quarantine and the all-endpoints-down fallback are each logged once. Exceptions that reach the + application are not logged a second time, per-stream and per-statement `DEBUG` messages and per-object metadata + messages are removed, and failures the client ignores are logged at `WARN` or `DEBUG` instead of `ERROR`. Public + API, configuration, retries, metrics and spans are unchanged. + (https://github.com/ClickHouse/clickhouse-java/issues/3295) diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java index c2487d2899..061bdc96a1 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java @@ -1,6 +1,7 @@ package com.clickhouse.jdbc; import com.clickhouse.client.api.DataTypeUtils; +import com.clickhouse.client.api.internal.ClientUtils; import com.clickhouse.client.api.metadata.TableSchema; import com.clickhouse.client.api.sql.SQLUtils; import com.clickhouse.data.ClickHouseColumn; @@ -429,9 +430,10 @@ public ResultSetMetaData getMetaData() throws SQLException { connection.getSchema(), connection.getCatalog(), tSchema.getTableName(), JdbcUtils.DATA_TYPE_CLASS_MAP, connection.getTypeMap()); } catch (Exception e) { - // Don't log the raw SQL (may carry sensitive literals); the cause is enough to diagnose. + // Only the type of the failure: the SQL and the server message (which can echo it) may carry + // sensitive literals. LOG.warn("Failed to resolve result-set metadata for prepared statement; " - + "falling back to untyped metadata", e); + + "falling back to untyped metadata: {}", ClientUtils.rootCauseClassName(e)); } } @@ -861,7 +863,6 @@ private String encodeObject(Object x, Long length) throws SQLException { return SQLUtils.escapeSingleQuotes(x.toString()); //Escape single quotes } catch (Exception e) { - LOG.error("Error encoding object", e); throw new SQLException("Error encoding object", ExceptionUtils.SQL_STATE_SQL_ERROR, e); } } @@ -988,7 +989,6 @@ private static String encodeCharacterStream(Reader reader, Long length) throws S reader.close(); } catch (IOException e) { - LOG.error("Error reading string from input stream", e); throw new SQLException("Error reading string from input stream", ExceptionUtils.SQL_STATE_SQL_ERROR, e); } diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/ResultSetImpl.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/ResultSetImpl.java index e91dd2e443..210aada2c9 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/ResultSetImpl.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/ResultSetImpl.java @@ -10,8 +10,6 @@ import com.clickhouse.jdbc.internal.FeatureManager; import com.clickhouse.jdbc.internal.JdbcUtils; import com.clickhouse.jdbc.metadata.ResultSetMetaDataImpl; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.io.ByteArrayInputStream; import java.io.InputStream; @@ -46,7 +44,6 @@ import java.util.function.Consumer; public class ResultSetImpl implements ResultSet, JdbcV2Wrapper { - private static final Logger log = LoggerFactory.getLogger(ResultSetImpl.class); private ResultSetMetaDataImpl metaData; protected ClickHouseFormatReader reader; private QueryResponse response; @@ -171,7 +168,6 @@ public void close() throws SQLException { try { reader.close(); } catch (Exception re) { - log.debug("Error closing reader", re); e = re; } finally { reader = null; @@ -182,7 +178,6 @@ public void close() throws SQLException { try { response.close(); } catch (Exception re) { - log.debug("Error closing response", re); e = re; } finally { response = null; diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java index 4ceb9da88d..358728e7ea 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java @@ -259,12 +259,11 @@ public ResultSet executeQuery(String sql) throws SQLException { private void closeCurrentResultSet() { if (currentResultSet != null) { - LOG.debug("Previous result set is open [resultSet = " + currentResultSet + "]"); // Closing request blindly assuming that user do not care about it anymore (DDL request for example) try { currentResultSet.close(); } catch (Exception e) { - LOG.error("Failed to close previous result set", e); + LOG.debug("Failed to close previous result set: {}", ClientUtils.rootCauseClassName(e)); } finally { currentResultSet = null; // no need to remember we have closed it already } @@ -282,7 +281,6 @@ protected String setLastQueryID(String queryId) { queryId = queryIdGenerator == null ? UUID.randomUUID().toString() : queryIdGenerator.get(); } lastQueryId = queryId; - LOG.debug("Query ID: {}", lastQueryId); return queryId; } @@ -305,7 +303,6 @@ protected ResultSetImpl executeQueryImpl(String sql, QuerySettings settings) thr QueryResponse response = null; try { lastStatementSql = parseJdbcEscapeSyntax(sql); - LOG.trace("SQL Query: {}", lastStatementSql); // this is not secure for create statements because of passwords if (queryTimeout == 0) { response = connection.getClient().query(lastStatementSql, mergedSettings).get(); } else { @@ -336,18 +333,21 @@ protected ResultSetImpl executeQueryImpl(String sql, QuerySettings settings) thr try { writtenRows = response.getWrittenRows(); } catch (Exception e) { - LOG.debug("Failed to read written-rows count from response; defaulting to 0", e); + LOG.debug("Failed to read written-rows count from response; defaulting to 0: {}", + ClientUtils.rootCauseClassName(e)); } this.currentUpdateCount = (int) Math.min(writtenRows, Integer.MAX_VALUE); try { reader.close(); } catch (Exception closeEx) { - LOG.warn("Failed to close reader when schema is null", closeEx); + LOG.debug("Failed to close reader when schema is null: {}", + ClientUtils.rootCauseClassName(closeEx)); } finally { try { response.close(); } catch (Exception closeRespEx) { - LOG.warn("Failed to close response when schema is null", closeRespEx); + LOG.debug("Failed to close response when schema is null: {}", + ClientUtils.rootCauseClassName(closeRespEx)); } } onResultSetClosed(null); @@ -359,7 +359,7 @@ protected ResultSetImpl executeQueryImpl(String sql, QuerySettings settings) thr try { response.close(); } catch (Exception ex) { - LOG.warn("Failed to close response after exception", ex); + LOG.debug("Failed to close response after exception: {}", ClientUtils.rootCauseClassName(ex)); } } handleSocketTimeoutException(e); @@ -405,7 +405,6 @@ protected long executeUpdateImpl(String sql, QuerySettings settings) throws SQLE QuerySettings mergedSettings = QuerySettings.merge(connection.getDefaultQuerySettings(), settings); mergedSettings.setQueryId(setLastQueryID(mergedSettings.getQueryId())); lastStatementSql = parseJdbcEscapeSyntax(sql); - LOG.trace("SQL Query: {}", lastStatementSql); int updateCount = 0; try (QueryResponse response = queryTimeout == 0 ? connection.getClient().query(lastStatementSql, mergedSettings).get() : connection.getClient().query(lastStatementSql, mergedSettings).get(queryTimeout, TimeUnit.SECONDS)) { @@ -440,7 +439,7 @@ public void close() throws SQLException { try { resultSet.close(); } catch (Exception e) { - LOG.error("Failed to close result set", e); + LOG.debug("Failed to close result set: {}", ClientUtils.rootCauseClassName(e)); } } } @@ -498,7 +497,7 @@ public void setQueryTimeout(int seconds) throws SQLException { getConnection().getClient().getConfiguration().getOrDefault(ClientConfigProperties.ASYNC_OPERATIONS.getKey(), ClientConfigProperties.ASYNC_OPERATIONS.getDefaultValue())); } catch (Exception e) { - LOG.error("Failed to read client configuration " + ClientConfigProperties.ASYNC_OPERATIONS.getKey(), e); + LOG.warn("Failed to read client configuration {}", ClientConfigProperties.ASYNC_OPERATIONS.getKey(), e); isAsyncEnabled = false; } @@ -527,13 +526,13 @@ public void cancel() throws SQLException { try (QueryResponse response = connection.getClient().query(String.format("KILL QUERY%sWHERE query_id = '%s'", connection.onCluster ? " ON CLUSTER " + SQLUtils.enquoteIdentifier(connection.cluster, true) + ' ' : ' ', queryId), cancelSettings).get()){ - LOG.debug("Query {} was killed by {}", queryId, response.getQueryId()); + // nothing to read: the query is cancelled } catch (Exception e) { ServerException se = ClientUtils.findCause(e, ServerException.class); if (se != null && se.getCode() == ServerException.NOTHING_TO_KILL) { // The query is not running (it is finished or not started yet). A server with `kill_throw_if_noop` // enabled (the default since 26.11) reports this as an error, but there is nothing to cancel. - LOG.debug("Query {} was not killed because it is not running: {}", queryId, se.getMessage()); + LOG.debug("Query was not killed because it is not running"); return; } throw new SQLException(e); diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/SqlParserFacade.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/SqlParserFacade.java index 9b5169604d..c2ca0287d4 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/SqlParserFacade.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/SqlParserFacade.java @@ -301,8 +301,7 @@ static void discardValuesListOfRecoveredParseTree(ParsedPreparedStatement stmt) */ static void assumeFunctionInValuesListOfRecoveredParseTree(ParsedPreparedStatement stmt) { if (stmt.isInsert()) { - LOG.debug("Assuming a function in the values list of an insert into {} that could not be parsed without errors", - stmt.getTable()); + LOG.debug("Assuming a function in the values list of an insert that could not be parsed without errors"); stmt.setUseFunction(true); } } @@ -323,7 +322,8 @@ protected ClickHouseParser parseSQL(String sql, ClickHouseParserBaseListener lis private static class ParserErrorListener extends BaseErrorListener { @Override public void syntaxError(Recognizer recognizer, Object offendingSymbol, int line, int charPositionInLine, String msg, RecognitionException e) { - LOG.debug("SQL syntax error at line: " + line + ", pos: " + charPositionInLine + ", " + msg); + // The message is not logged: it quotes the tokens of the statement. + LOG.debug("SQL syntax error at line: {}, pos: {}", line, charPositionInLine); } } diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java index 1a9663a477..4469f5601a 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java @@ -14,8 +14,6 @@ import com.clickhouse.jdbc.internal.ExceptionUtils; import com.clickhouse.jdbc.internal.JdbcUtils; import com.google.common.collect.ImmutableMap; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import java.sql.Connection; import java.sql.JDBCType; @@ -38,7 +36,6 @@ import java.util.stream.Collectors; public class DatabaseMetaDataImpl implements java.sql.DatabaseMetaData, JdbcV2Wrapper { - private static final Logger log = LoggerFactory.getLogger(DatabaseMetaDataImpl.class); private static final int JDBC_SPEC_MAJOR_VERSION = 4; private static final int JDBC_SPEC_MINOR_VERSION = 2; @@ -999,7 +996,6 @@ public static boolean isSystemTableEngine(String engine) { */ @Override public ResultSet getTables(String catalog, String schemaPattern, String tableNamePattern, String[] types) throws SQLException { - log.debug("getTables: catalog={}, schemaPattern={}, tableNamePattern={}, types={}", catalog, schemaPattern, tableNamePattern, types); // TODO: when switch between catalog and schema is implemented, then TABLE_SCHEMA and TABLE_CAT should be populated accordingly // TODO: handle useCatalogs == true and return schema catalog name @@ -1208,7 +1204,6 @@ private static String generateSqlTypeSizes(String columnName) { ClickHouseDataType dt = c.getDataType(); type = JdbcUtils.convertToSqlType(dt); } catch (Exception e) { - log.debug("Failed to convert column data type to SQL type: " + typeName, e); type = JDBCType.OTHER; // In case of error, return SQL type 0 } } @@ -1421,10 +1416,8 @@ public ResultSet getTypeInfo() throws SQLException { try { type = JdbcUtils.convertToSqlType(ClickHouseDataType.valueOf(typeName)); } catch (IllegalArgumentException e) { - log.debug("Unknown type: {}. Please check for a new version of the client.", typeName); type = JDBCType.OTHER; } catch (Exception e) { - log.debug("Failed to get SQL type for type: " + typeName, e); type = JDBCType.OTHER; } } @@ -1819,7 +1812,6 @@ public int getDatabaseMinorVersion() throws SQLException { try { return Integer.parseInt(version.split("\\.")[1]); } catch (NumberFormatException e) { - log.error("Failed to parse minor version from server version: " + version, e); throw new SQLException("Failed to parse minor version from server version: " + version, ExceptionUtils.SQL_STATE_CLIENT_ERROR, e); } } diff --git a/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/ShowStatementsMetaData.java b/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/ShowStatementsMetaData.java index 5fd4f2eb23..7fcb6669bf 100644 --- a/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/ShowStatementsMetaData.java +++ b/jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/ShowStatementsMetaData.java @@ -143,6 +143,7 @@ ResultSet getColumns(String schemaPattern, String tableNamePattern, String colum Predicate columnNameMatcher = likeMatcher(columnNamePattern); List> records = new ArrayList<>(); try { + int skipped = 0; for (String[] table : showTables(schemaPattern, tableNamePattern, true)) { try { records.addAll(describeTable(table[0], table[1], columnNameMatcher)); @@ -150,9 +151,10 @@ ResultSet getColumns(String schemaPattern, String tableNamePattern, String colum if (!isSkippedObjectError(e)) { throw e; } - log.debug("Skipped metadata of table {}", table[0].isEmpty() ? table[1] : table[0] + "." + table[1], e); + skipped++; } } + logSkipped(skipped, "tables"); } catch (Exception e) { throw ExceptionUtils.toSqlState(e); } @@ -192,6 +194,7 @@ private List showTables(String schemaPattern, String tableNamePattern, if (includeTemporary && likeMatcher(schemaPattern).test("")) { tables.addAll(showTablesOfDatabase("", tableNamePattern)); } + int skipped = 0; for (String database : showDatabases(schemaPattern)) { try { tables.addAll(showTablesOfDatabase(database, tableNamePattern)); @@ -199,9 +202,10 @@ private List showTables(String schemaPattern, String tableNamePattern, if (!isSkippedObjectError(e)) { throw e; } - log.debug("Skipped metadata of database {}", database, e); + skipped++; } } + logSkipped(skipped, "databases"); return tables; } @@ -322,7 +326,7 @@ private static void putColumnSizes(Map record, String type) { } } } catch (Exception e) { - log.debug("Failed to parse column type: {}", type, e); + // An unknown type has no sizes. Not logged: this runs for every column. } Integer byteLength = TYPE_NAME_TO_BYTE_LENGTH.get(type); record.put("COLUMN_SIZE", octetLength != null ? octetLength @@ -349,6 +353,17 @@ private static boolean isSkippedObjectError(SQLException e) { return SKIPPED_OBJECT_ERROR_CODES.contains(e.getErrorCode()); } + /** + * Logs one message per metadata call, with the count only: the names of the objects are not logged, and a call + * over many objects does not log one message per object. + */ + private static void logSkipped(int skipped, String objects) { + if (skipped > 0) { + log.debug("Skipped metadata of {} {} that were dropped, cannot be described, or cannot be read", + skipped, objects); + } + } + /** * Returns a matcher with the semantics of the ClickHouse LIKE operator: {@code %} matches any sequence of * characters, {@code _} matches one character and {@code \} escapes the next character. A {@code null} pattern diff --git a/jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj b/jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj index ae4270ce42..7a131fb67e 100644 --- a/jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj +++ b/jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj @@ -98,8 +98,9 @@ public class ClickHouseSqlParser { if (DEBUG) { throw new IllegalArgumentException(e); } else { - log.warn("Failed to parse SQL. If you believe the SQL is valid, please feel free to open an issue on GitHub with this warning. Enable DEBUG logging for details."); - log.debug("Failed to parse SQL: '" + sql + "'", e); + // Neither the SQL nor the parser error is logged at any level: the error quotes the statement, + // which can carry credentials or other sensitive literals. + log.warn("Failed to parse SQL. If you believe the SQL is valid, please feel free to open an issue on GitHub with this warning and the statement, with any sensitive values removed."); } } diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/JDBCErrorHandlingTests.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/JDBCErrorHandlingTests.java index b7bae4a66d..f5087dd27d 100644 --- a/jdbc-v2/src/test/java/com/clickhouse/jdbc/JDBCErrorHandlingTests.java +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/JDBCErrorHandlingTests.java @@ -56,10 +56,10 @@ public void testQueryIDPropagatedToException() throws Exception { /** * When result-set metadata cannot be resolved because the DESCRIBE fails (here: an unknown table), * {@code getMetaData()} must fall back to untyped metadata instead of throwing, and the failure must - * be logged at WARN with the exception cause attached (the previous log dropped the cause). + * be logged at WARN naming the type of the failure, without the SQL or the server message that echoes it. */ @Test(groups = {"integration"}) - public void testPreparedStatementMetadataFallbackLogsCause() throws Exception { + public void testPreparedStatementMetadataFallbackLogsNoSql() throws Exception { String sql = "SELECT c FROM nonexistent_table_for_metadata_logging WHERE id = ?"; PrintStream original = System.err; @@ -77,10 +77,10 @@ public void testPreparedStatementMetadataFallbackLogsCause() throws Exception { // The fallback returns metadata rather than throwing or returning null. Assert.assertNotNull(md, "metadata must fall back to untyped columns, not be null"); - // The fallback is logged at WARN and now carries the exception cause (the old log omitted it). Assert.assertTrue(logged.contains("Failed to resolve result-set metadata"), "the metadata fallback must be logged at WARN: " + logged); - Assert.assertTrue(logged.contains("Exception"), - "the exception cause must be attached to the log: " + logged); + Assert.assertTrue(logged.contains("Exception"), "the type of the failure must be logged: " + logged); + Assert.assertFalse(logged.contains("nonexistent_table_for_metadata_logging"), + "neither the SQL nor the server message may be logged: " + logged); } } diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/LoggingTestUtils.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/LoggingTestUtils.java new file mode 100644 index 0000000000..dc4def21cb --- /dev/null +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/LoggingTestUtils.java @@ -0,0 +1,55 @@ +package com.clickhouse.jdbc; + +import org.slf4j.LoggerFactory; +import org.slf4j.simple.SimpleLogger; + +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.lang.reflect.Field; +import java.nio.charset.StandardCharsets; +import java.util.HashMap; +import java.util.List; +import java.util.Map; + +/** + * Captures the output of slf4j-simple, the test logging backend, with chosen loggers at a chosen level. + */ +public final class LoggingTestUtils { + + /** An action that may throw; its exception is rethrown after the output is captured. */ + public interface Action { + void run() throws Exception; + } + + private LoggingTestUtils() { + } + + /** + * Runs {@code action} with every logger in {@code loggers} at {@code level} and returns what was logged. + * slf4j-simple caches loggers by name, so the level applies to a logger whether or not its class is loaded yet. + * slf4j-simple writes to {@code System.err} and looks it up for every message, so it is swapped for the capture. + */ + public static String captureLogs(List loggers, int level, Action action) throws Exception { + Field levelField = SimpleLogger.class.getDeclaredField("currentLogLevel"); + levelField.setAccessible(true); + Map previous = new HashMap<>(); + for (String name : loggers) { + Object logger = LoggerFactory.getLogger(name); + previous.put(logger, levelField.getInt(logger)); + levelField.setInt(logger, level); + } + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + PrintStream originalErr = System.err; + System.setErr(new PrintStream(captured, true, "UTF-8")); + try { + action.run(); + } finally { + System.err.flush(); + System.setErr(originalErr); + for (Map.Entry entry : previous.entrySet()) { + levelField.setInt(entry.getKey(), entry.getValue()); + } + } + return new String(captured.toByteArray(), StandardCharsets.UTF_8); + } +} diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/StatementLoggingTest.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/StatementLoggingTest.java new file mode 100644 index 0000000000..e419167fc4 --- /dev/null +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/StatementLoggingTest.java @@ -0,0 +1,110 @@ +package com.clickhouse.jdbc; + +import com.clickhouse.client.api.ClientConfigProperties; +import com.github.tomakehurst.wiremock.WireMockServer; +import com.github.tomakehurst.wiremock.client.WireMock; +import com.github.tomakehurst.wiremock.common.ConsoleNotifier; +import com.github.tomakehurst.wiremock.core.WireMockConfiguration; +import org.slf4j.spi.LocationAwareLogger; +import org.testng.annotations.DataProvider; +import org.testng.annotations.Test; + +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.SQLException; +import java.sql.Statement; +import java.util.Arrays; +import java.util.List; +import java.util.Properties; + +import static org.testng.Assert.assertFalse; +import static org.testng.Assert.assertTrue; +import static org.testng.Assert.expectThrows; + +/** + * With every driver and client logger at TRACE, executing a statement logs neither its SQL nor its bound values, + * whether the server accepts it or returns an error that echoes it. The server is mocked: no user is created. + */ +public class StatementLoggingTest { + + private static final String CANARY_PASSWORD = "canary-password-5e2a"; + private static final String CANARY_VALUE = "canary-value-8b1c"; + private static final String CANARY_ERROR = "canary-error-3d9f"; + private static final String CANARY_QUERY_ID = "canary-query-id-7c4e"; + + private static final List LOGGERS = Arrays.asList( + "com.clickhouse.jdbc.ConnectionImpl", + "com.clickhouse.jdbc.PreparedStatementImpl", + "com.clickhouse.jdbc.StatementImpl", + "com.clickhouse.jdbc.internal.SqlParserFacade", + "com.clickhouse.jdbc.internal.parser.javacc.ClickHouseSqlParser", + "com.clickhouse.client.api.Client", + "com.clickhouse.client.api.internal.HttpAPIClientHelper", + "com.clickhouse.client.api.transport.ClientNodeSelector"); + + @DataProvider + public static Object[][] statementLoggingDP() { + return new Object[][] { + // SQL parser, prepared statement, server error + {"JAVACC", false, false}, + {"JAVACC", true, false}, + {"ANTLR4", false, true}, + {"ANTLR4_PARAMS_PARSER", true, true}, + }; + } + + @Test(groups = {"unit"}, dataProvider = "statementLoggingDP") + public void testStatementLogsNoSqlOrValues(String parser, boolean prepared, boolean serverError) throws Exception { + WireMockServer server = new WireMockServer(WireMockConfiguration.options().dynamicPort() + .notifier(new ConsoleNotifier(false))); + server.start(); + try { + server.stubFor(WireMock.post(WireMock.anyUrl()).willReturn(serverError + ? WireMock.serverError().withHeader("X-ClickHouse-Exception-Code", "62") + .withBody("Code: 62. DB::Exception: " + CANARY_ERROR + " near '" + CANARY_PASSWORD + "'") + : WireMock.ok())); + + Properties properties = new Properties(); + properties.setProperty(ClientConfigProperties.COMPRESS_SERVER_RESPONSE.getKey(), "false"); + properties.setProperty(ClientConfigProperties.SERVER_TIMEZONE.getKey(), "UTC"); // no server info query + properties.setProperty(DriverProperties.SQL_PARSER.getKey(), parser); + properties.put(DriverProperties.QUERY_ID_GENERATOR.getKey(), + (java.util.function.Supplier) () -> CANARY_QUERY_ID); + + String logged = LoggingTestUtils.captureLogs(LOGGERS, LocationAwareLogger.TRACE_INT, () -> { + try (Connection conn = new ConnectionImpl("jdbc:clickhouse://localhost:" + server.port() + "/default", + properties)) { + if (serverError) { + SQLException e = expectThrows(SQLException.class, () -> execute(conn, prepared)); + assertTrue(e.getMessage().contains(CANARY_ERROR), "the server error must reach the caller"); + } else { + execute(conn, prepared); + } + } + }); + + server.verify(WireMock.postRequestedFor(WireMock.anyUrl()) + .withRequestBody(WireMock.containing(prepared ? CANARY_VALUE : CANARY_PASSWORD))); + for (String canary : Arrays.asList(CANARY_PASSWORD, CANARY_VALUE, CANARY_ERROR, CANARY_QUERY_ID, + "canary_user")) { + assertFalse(logged.contains(canary), "'" + canary + "' must not be logged: " + logged); + } + } finally { + server.stop(); + } + } + + private static void execute(Connection conn, boolean prepared) throws SQLException { + if (prepared) { + try (PreparedStatement ps = conn.prepareStatement( + "ALTER USER canary_user IDENTIFIED BY 'x' SETTINGS custom_tag = ?")) { + ps.setString(1, CANARY_VALUE); + ps.executeUpdate(); + } + } else { + try (Statement stmt = conn.createStatement()) { + stmt.executeUpdate("CREATE USER IF NOT EXISTS canary_user IDENTIFIED BY '" + CANARY_PASSWORD + "'"); + } + } + } +} diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java index 4fd88c07b7..2a05d9caca 100644 --- a/jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java @@ -2,10 +2,11 @@ import com.clickhouse.jdbc.internal.parser.javacc.ClickHouseSqlParser; import com.clickhouse.jdbc.internal.parser.javacc.ClickHouseSqlStatement; +import com.clickhouse.jdbc.LoggingTestUtils; +import org.slf4j.spi.LocationAwareLogger; import org.testng.annotations.Test; -import java.io.ByteArrayOutputStream; -import java.io.PrintStream; +import java.util.Collections; import static org.testng.Assert.assertFalse; import static org.testng.Assert.assertNotNull; @@ -13,21 +14,20 @@ import static org.testng.Assert.fail; /** - * Verifies that a parse failure does not expose the SQL statement or the parser error detail at - * {@code WARN}. The statement that failed to parse can carry credentials or PII, so the {@code WARN} - * stays a generic message; the raw SQL and the parser exception are only acceptable at {@code DEBUG}. + * Verifies that a parse failure exposes neither the SQL statement nor the parser error detail at any level. The + * statement that failed to parse can carry credentials or PII, so only a generic {@code WARN} is logged. */ public class ClickHouseSqlParserLoggingTest { @Test(groups = { "unit" }) - public void testParseFailureWarnDoesNotExposeSql() throws Exception { + public void testParseFailureLogsNoSql() throws Exception { String secret = "s3cret_db_" + System.nanoTime(); // A trailing identifier after USE is unexpected, so parsing fails with the token echoed // in the parser error message. String sql = "USE " + secret + " " + secret; // Precondition: the raw parser error embeds the offending SQL token, so logging it (or the - // SQL) at WARN would expose statement contents. + // SQL) would expose statement contents. String rawError = null; try { new ClickHouseSqlParser(sql, null).sql(); @@ -38,33 +38,18 @@ public void testParseFailureWarnDoesNotExposeSql() throws Exception { assertNotNull(rawError, "parser error should carry a message"); assertTrue(rawError.contains(secret), "the parser error is expected to embed the SQL token"); - ByteArrayOutputStream captured = new ByteArrayOutputStream(); - PrintStream originalErr = System.err; - System.setErr(new PrintStream(captured, true, "UTF-8")); - ClickHouseSqlStatement[] stmts; - try { - stmts = ClickHouseSqlParser.parse(sql, null); - } finally { - System.err.flush(); - System.setErr(originalErr); - } + ClickHouseSqlStatement[][] stmts = new ClickHouseSqlStatement[1][]; + String logged = LoggingTestUtils.captureLogs( + Collections.singletonList(ClickHouseSqlParser.class.getName()), LocationAwareLogger.TRACE_INT, + () -> stmts[0] = ClickHouseSqlParser.parse(sql, null)); // A parse failure degrades to a single fallback statement rather than throwing. - assertNotNull(stmts); - assertTrue(stmts.length >= 1); + assertNotNull(stmts[0]); + assertTrue(stmts[0].length >= 1); - // WARN is always enabled, so the parse-failure warning is emitted here regardless of the - // DEBUG configuration. Isolate the WARN-level line(s) and assert they neither echo the parser - // error nor expose the SQL token (both belong only at DEBUG). - StringBuilder warnLines = new StringBuilder(); - for (String line : captured.toString("UTF-8").split("\\R")) { - if (line.contains(" WARN ") && line.contains("ClickHouseSqlParser")) { - warnLines.append(line).append('\n'); - } - } - String warn = warnLines.toString(); - assertFalse(warn.isEmpty(), "expected a parse-failure WARN to be emitted"); - assertFalse(warn.contains(secret), "parse-failure WARN exposed the SQL token:\n" + warn); - assertFalse(warn.contains("Encountered"), "parse-failure WARN echoed the parser error detail:\n" + warn); + assertTrue(logged.contains(" WARN ") && logged.contains("Failed to parse SQL"), + "expected a parse-failure WARN to be emitted:\n" + logged); + assertFalse(logged.contains(secret), "the parse failure exposed the SQL token:\n" + logged); + assertFalse(logged.contains("Encountered"), "the parse failure echoed the parser error detail:\n" + logged); } } diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataTest.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataTest.java index 54d763bf93..b7f4b68049 100644 --- a/jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataTest.java +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataTest.java @@ -7,15 +7,14 @@ import com.clickhouse.jdbc.ClientInfoProperties; import com.clickhouse.jdbc.DriverProperties; import com.clickhouse.jdbc.JdbcIntegrationTest; +import com.clickhouse.jdbc.LoggingTestUtils; import com.clickhouse.jdbc.internal.JdbcUtils; +import org.slf4j.spi.LocationAwareLogger; import org.testng.Assert; import org.testng.SkipException; import org.testng.annotations.DataProvider; import org.testng.annotations.Test; -import java.io.ByteArrayOutputStream; -import java.io.PrintStream; -import java.lang.reflect.Field; import java.sql.Connection; import java.sql.DatabaseMetaData; import java.sql.ResultSet; @@ -542,66 +541,32 @@ public void testGetTables() throws Exception { } /** - * Regression test for issue #2970. {@code DatabaseMetaDataImpl} previously logged through the - * deprecated {@code com.clickhouse.logging} facade, which formats with {@link java.util.Formatter} - * ({@code %s}); its SLF4J-style {@code "{}"} placeholders therefore rendered literally instead of - * substituting the arguments. The class was migrated to SLF4J so the placeholders substitute. - * - *

The migration is pinned deterministically by asserting the logger facade is an - * {@link org.slf4j.Logger} (independent of the active logging backend or level): the old - * {@code com.clickhouse.logging.Logger} is a different type, so a revert fails this assertion. - * When DEBUG is enabled for this logger — the default test binding via {@code simplelogger.properties} - * — the test additionally captures {@code System.err} around a {@code getTables} call and confirms the - * emitted DEBUG line substitutes its arguments at runtime. Some CI jobs (e.g. the coverage job) run - * without {@code simplelogger.properties}, disabling DEBUG; there the capture is skipped and the facade - * assertion still guards the regression. + * Metadata calls log neither their arguments, which the application supplies, nor the names of the objects + * they read, even with every driver logger at TRACE. */ @Test(groups = { "integration" }) - public void testGetTablesDebugSubstitutesPlaceholders() throws Exception { - Field logField = DatabaseMetaDataImpl.class.getDeclaredField("log"); - logField.setAccessible(true); - Object logger = logField.get(null); - assertTrue(logger instanceof org.slf4j.Logger, - "DatabaseMetaDataImpl must log via org.slf4j.Logger so '{}' placeholders substitute, was: " - + (logger == null ? "null" : logger.getClass().getName())); - - // slf4j-simple derives a logger's level at creation time from simplelogger.properties / system - // properties; the coverage CI job strips simplelogger.properties, so DEBUG is off there and there - // is nothing to capture. Only attempt the runtime capture when DEBUG is actually emitted. - if (!((org.slf4j.Logger) logger).isDebugEnabled()) { - return; - } - - final String schemaProbe = "log_placeholder_probe_" + System.nanoTime(); - final ByteArrayOutputStream captured = new ByteArrayOutputStream(); - final PrintStream originalErr = System.err; - final String logged; + public void testMetadataCallsLogNoPatterns() throws Exception { + final String schemaProbe = "log_schema_probe_" + System.nanoTime(); + final String tableProbe = "log_table_probe_" + System.nanoTime(); + String logged; try (Connection conn = getJdbcConnection()) { DatabaseMetaData dbmd = conn.getMetaData(); - // slf4j-simple (the jdbc-v2 test binding) writes to System.err, so the getTables entry log - // is emitted and captured here. - System.setErr(new PrintStream(captured, true, "UTF-8")); - try (ResultSet rs = dbmd.getTables(null, schemaProbe, "no_such_table%", null)) { - // getTables logs its four arguments at DEBUG on entry; the lookup itself matches nothing. - } finally { - System.err.flush(); - System.setErr(originalErr); - } - logged = captured.toString("UTF-8"); - } - // The logger-facade assertion above is the deterministic guard; the System.err capture is - // best-effort (a cached stream or a non-slf4j-simple binding could yield nothing), so the - // substitution assertions only run when output was actually captured. - if (logged.isEmpty()) { - return; + logged = LoggingTestUtils.captureLogs(Arrays.asList( + "com.clickhouse.jdbc.metadata.ShowStatementsMetaData", "com.clickhouse.jdbc.StatementImpl", + "com.clickhouse.jdbc.PreparedStatementImpl", "com.clickhouse.jdbc.internal.SqlParserFacade"), + LocationAwareLogger.TRACE_INT, () -> { + try (ResultSet rs = dbmd.getTables(null, schemaProbe, tableProbe + "%", null)) { + assertFalse(rs.next()); + } + try (ResultSet rs = dbmd.getColumns(null, schemaProbe, tableProbe, null)) { + assertFalse(rs.next()); + } + }); } - assertFalse(logged.contains("catalog={}"), - "getTables logged a literal '{}' placeholder instead of substituting its arguments:\n" + logged); - assertTrue(logged.contains(schemaProbe), - "getTables did not substitute the schemaPattern argument into its DEBUG log:\n" + logged); + assertFalse(logged.contains(schemaProbe), "the schema pattern must not be logged:\n" + logged); + assertFalse(logged.contains(tableProbe), "the table pattern must not be logged:\n" + logged); } - @Test(groups = { "integration" }) public void testGetPrimaryKeys() throws Exception { if (isCloud()) {