[client-v2, jdbc-v2] Fix bad and noisy logging (#2970)

CHANGELOG.md

@@ -19,6 +19,8 @@
 
 ### Bug Fixes 
 
+- **[client-v2, jdbc-v2]** Reduced noisy and potentially sensitive logging; SQL that fails to parse is no
+  longer logged at `WARN` (it could contain credentials/PII). (https://github.com/ClickHouse/clickhouse-java/issues/2970)
 - **[client-v2]** Fixed `BigDecimal` values written into a `Dynamic` column being silently truncated when the
   value's scale exceeded the inferred width's maximum scale, and throwing an overflow error when the value
   carried an integer part (e.g. `19.99`). The `Dynamic` type inference now sizes the `Decimal` width to hold
@@ -31,7 +33,6 @@
   serialized identically to its underlying type `T`, writing the `Nullable` null-marker byte when the
   underlying type is nullable (e.g. `SimpleAggregateFunction(anyLast, Nullable(String))`), mirroring the
   read path. (https://github.com/ClickHouse/clickhouse-java/issues/2477)
-
 - **[client-v2, jdbc-v2]** Fixed several logging-layer defects. In `client-v2`, `HttpAPIClientHelper.shouldRetry`
   threw a `ClassCastException` when a retryable `ServerException` was wrapped as the *cause* of another exception
   (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

@@ -1499,8 +1499,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,
                     lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
                     if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(queryId)) {
                         if (i < maxAttempts) {
-                            LOG.warn("Retrying.", e);
-                            selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
+                            selectedEndpoint = logRetryAndSelectNextNode("Insert", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
                         } else {
                             nodeSelector.getNextAliveNode(selectedEndpoint);
                         }
@@ -1705,8 +1704,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,
                         lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
                         if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(requestSettings.getQueryId())) {
                             if (i < maxAttempts) {
-                                LOG.warn("Retrying.", e);
-                                selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
+                                selectedEndpoint = logRetryAndSelectNextNode("Insert (stream)", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
                             } else {
                                 nodeSelector.getNextAliveNode(selectedEndpoint);
                             }
@@ -1849,8 +1847,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
                             lastException = httpClientHelper.wrapException(msg, e, requestSettings.getQueryId());
                             if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings()) && requestIsNotCancelled(requestSettings.getQueryId())) {
                                 if (i < maxAttempts) {
-                                    LOG.warn("Retrying.", e);
-                                    selectedEndpoint = nodeSelector.getNextAliveNode(selectedEndpoint);
+                                    selectedEndpoint = logRetryAndSelectNextNode("Query", i, maxAttempts, requestSettings.getQueryId(), selectedEndpoint, e);
                                 } else {
                                     nodeSelector.getNextAliveNode(selectedEndpoint);
                                 }
@@ -1871,6 +1868,19 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
         return runAsyncOperation(responseSupplier, requestSettings.getAllSettings());
     }
 
+    /**
+     * Logs a single consolidated warning for a failed but retryable request attempt and returns
+     * the next endpoint to try. Keeping this in one place ensures a retry is logged exactly once
+     * with a consistent shape across the insert and query paths.
+     */
+    private Endpoint logRetryAndSelectNextNode(String operation, int attemptIndex, int maxAttempts,
+                                               String queryId, Endpoint endpoint, Exception cause) {
+        LOG.warn("{} failed (attempt {} of {}, queryId: {}), endpoint: {}, cause: {}: {}. Retrying.",
+                operation, attemptIndex + 1, maxAttempts + 1, queryId, endpoint,
+                cause.getClass().getName(), cause.getMessage());
+        return nodeSelector.getNextAliveNode(endpoint);
+    }
+
     private void registerTransportReq(String queryId, TransportRequest tr) {
         if (queryId != null) {
             ongoingRequests.put(queryId, tr);

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

@@ -27,7 +27,7 @@ public class ClickHouseLZ4InputStream extends InputStream {
 
     public ClickHouseLZ4InputStream(InputStream in, LZ4FastDecompressor decompressor, int bufferSize) {
         super();
-        LOG.debug("Using decompressor {}", decompressor);
+        LOG.debug("Using LZ4 decompressor with buffer size {}", bufferSize);
         this.decompressor = decompressor;
         this.in = in;
         this.buffer = ByteBuffer.allocate(bufferSize);
@@ -137,7 +137,6 @@ private int refill() throws IOException {
 
         if (buffer.capacity() < uncompressedSize) {
             buffer = ByteBuffer.allocate(uncompressedSize);
-            LOG.debug("Buffer size is too small, reallocate buffer with size: {}", uncompressedSize);
         }
         decompressor.decompress(ByteBuffer.wrap(block), offset,  buffer, 0, uncompressedSize);
         buffer.position(0);

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

@@ -29,7 +29,7 @@ public class ClickHouseLZ4OutputStream extends OutputStream {
 
     public ClickHouseLZ4OutputStream(OutputStream out, LZ4Compressor compressor, int bufferSize) {
         super();
-        LOG.debug("Using compressor {}", compressor);
+        LOG.debug("Using LZ4 compressor with buffer size {}", bufferSize);
         this.inBuffer = ByteBuffer.allocate(bufferSize);
         this.out = out;
         this.compressor = compressor;

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

@@ -732,10 +732,10 @@ public TransportResponse executeRequest(TransportRequest transportRequest) throw
                     throw new ClientException("Unexpected result status " + statusCode);
             }
         } catch (UnknownHostException e) {
-            LOG.warn("Host '{}' unknown", req.getAuthority());
+            LOG.debug("Host '{}' unknown", req.getAuthority());
             throw e;
         } catch (ConnectException | NoRouteToHostException e) {
-            LOG.warn("Failed to connect to '{}': {}", req.getAuthority(), e.getMessage());
+            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);
@@ -918,9 +918,6 @@ private HttpEntity wrapRequestEntity(HttpEntity httpEntity, Map<String, Object>
         boolean useHttpCompression = ClientConfigProperties.USE_HTTP_COMPRESSION.getOrDefault(requestConfig);
         boolean appCompressedData = ClientConfigProperties.APP_COMPRESSED_DATA.getOrDefault(requestConfig);
 
-        LOG.debug("wrapRequestEntity: client compression: {}, http compression: {}, content encoding: {}",
-                clientCompression, useHttpCompression, httpEntity.getContentEncoding());
-
         if (httpEntity.getContentEncoding() != null && !appCompressedData) {
             // http header is set and data is not compressed
             return new CompressedEntity(httpEntity, false, CompressorStreamFactory.getSingleton());
@@ -937,9 +934,6 @@ private HttpEntity wrapResponseEntity(HttpEntity httpEntity, int httpStatus, Map
         boolean serverCompression = ClientConfigProperties.COMPRESS_SERVER_RESPONSE.getOrDefault(requestConfig);
         boolean useHttpCompression = ClientConfigProperties.USE_HTTP_COMPRESSION.getOrDefault(requestConfig);
 
-        LOG.debug("wrapResponseEntity: server compression: {}, http compression: {}, content encoding: {}",
-                serverCompression, useHttpCompression, httpEntity.getContentEncoding());
-
         if (httpEntity.getContentEncoding() != null) {
             // http compressed response
             return new CompressedEntity(httpEntity, true, CompressorStreamFactory.getSingleton());

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

@@ -8,7 +8,10 @@
 import org.testng.Assert;
 import org.testng.annotations.Test;
 
+import java.io.ByteArrayOutputStream;
+import java.io.PrintStream;
 import java.util.concurrent.TimeUnit;
+import java.util.regex.Pattern;
 
 public class ClientFailoverUnitTest {
 
@@ -39,4 +42,47 @@ public void testWireMockFailoverOnly() throws Exception {
             mockServer.stop();
         }
     }
+
+    @Test
+    public void testRetryWarnNamesExceptionClass() throws Exception {
+        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
+            }
+        } finally {
+            System.err.flush();
+            System.setErr(originalErr);
+        }
+
+        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 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);
+    }
 }

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

@@ -96,9 +96,7 @@ public ConnectionImpl(String url, Properties info) throws SQLException {
                 clientName = this.appName + " " + clientName; // Use the application name as client name
             }
 
-            if (this.config.isDisableFrameworkDetection()) {
-                LOG.debug("Framework detection is disabled.");
-            } else {
+            if (!this.config.isDisableFrameworkDetection()) {
                 String detectedFrameworks = Driver.FrameworksDetection.getFrameworksDetected();
                 LOG.debug("Detected frameworks: {}", detectedFrameworks);
                 if (!detectedFrameworks.trim().isEmpty()) {

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

@@ -62,10 +62,7 @@ public static String getFrameworksDetected() {
     public static final String DRIVER_CLIENT_NAME = "jdbc-v2/";
 
     static {
-        log.debug("Initializing ClickHouse JDBC driver V2");
-
         driverVersion = ClickHouseClientOption.readVersionFromResource("jdbc-v2-version.properties");
-        log.debug("ClickHouse JDBC driver version: {}", driverVersion);
 
         int[] versions = parseVersion(driverVersion);
 

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

@@ -748,8 +748,6 @@ private String encodeObject(Object x) throws SQLException {
     private static final char C_BRACKET = ']';
 
     private String encodeObject(Object x, Long length) throws SQLException {
-        LOG.trace("Encoding object: {}", x);
-
         try {
             if (x == null) {
                 return "NULL";

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

@@ -78,11 +78,9 @@ protected void ensureOpen() throws SQLException {
     }
 
     private String parseJdbcEscapeSyntax(String sql) {
-        LOG.trace("Original SQL: {}", sql);
         if (escapeProcessingEnabled) {
             sql = escapedSQLToNative(sql);
         }
-        LOG.trace("Escaped SQL: {}", sql);
         return sql;
     }
 

jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/ExceptionUtils.java

@@ -4,8 +4,6 @@
 import com.clickhouse.client.api.ClientMisconfigurationException;
 import com.clickhouse.client.api.ConnectionInitiationException;
 import com.clickhouse.client.api.ServerException;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
 
 import java.net.MalformedURLException;
 import java.sql.SQLDataException;
@@ -15,7 +13,6 @@
  * Helper class for building {@link SQLException}.
  */
 public final class ExceptionUtils {
-    private static final Logger log = LoggerFactory.getLogger(ExceptionUtils.class);
     public static final String SQL_STATE_CLIENT_ERROR = "HY000";
     public static final String SQL_STATE_OPERATION_CANCELLED = "HY008";
     public static final String SQL_STATE_CONNECTION_EXCEPTION = "08000";
@@ -50,8 +47,6 @@ public static SQLException toSqlState(Exception cause) {
      * @return Converted {@link SQLException}
      */
     public static SQLException toSqlState(String message, String debugMessage, Exception cause) {
-        log.debug("Exception Message: {}, Debug message: {}", message, debugMessage, cause);
-
         if (cause == null) {
             return new SQLException(message == null ? "Unknown client error" : message, SQL_STATE_CLIENT_ERROR);
         }

jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java

@@ -11,9 +11,9 @@
 import com.clickhouse.jdbc.internal.DetachedResultSet;
 import com.clickhouse.jdbc.internal.ExceptionUtils;
 import com.clickhouse.jdbc.internal.JdbcUtils;
-import com.clickhouse.logging.Logger;
-import com.clickhouse.logging.LoggerFactory;
 import com.google.common.collect.ImmutableMap;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import java.sql.Connection;
 import java.sql.JDBCType;
@@ -1132,7 +1132,7 @@ private static String generateSqlTypeSizes(String columnName) {
                 ClickHouseDataType dt = c.getDataType();
                 type = JdbcUtils.convertToSqlType(dt);
             } catch (Exception e) {
-                log.error("Failed to convert column data type to SQL type: {}", typeName, 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
             }
         }
@@ -1339,10 +1339,10 @@ public ResultSet getTypeInfo() throws SQLException {
             try {
                 type = JdbcUtils.convertToSqlType(ClickHouseDataType.valueOf(typeName));
             } catch (IllegalArgumentException e) {
-                log.error("Unknown type: " + typeName + ". Please check for a new version of the client.");
+                log.debug("Unknown type: {}. Please check for a new version of the client.", typeName);
                 type = JDBCType.OTHER;
             } catch (Exception e) {
-                log.error("Failed to get SQL type for type: " + typeName, e);
+                log.debug("Failed to get SQL type for type: " + typeName, e);
                 type = JDBCType.OTHER;
             }
         }

jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj

@@ -41,8 +41,8 @@ import java.util.HashSet;
 import java.util.Collection;
 
 import com.clickhouse.client.ClickHouseConfig;
-import com.clickhouse.logging.Logger;
-import com.clickhouse.logging.LoggerFactory;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class ClickHouseSqlParser {
     private static final boolean DEBUG = false;
@@ -98,7 +98,8 @@ public class ClickHouseSqlParser {
             if (DEBUG) {
                 throw new IllegalArgumentException(e);
             } else {
-                log.warn("%s. If you believe the SQL is valid, please feel free to open an issue on Github with this warning and the following SQL attached.\n%s", e.getMessage(), sql);
+                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);
             }
         }
 

jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java

@@ -0,0 +1,70 @@
+package com.clickhouse.jdbc.internal;
+
+import com.clickhouse.jdbc.internal.parser.javacc.ClickHouseSqlParser;
+import com.clickhouse.jdbc.internal.parser.javacc.ClickHouseSqlStatement;
+import org.testng.annotations.Test;
+
+import java.io.ByteArrayOutputStream;
+import java.io.PrintStream;
+
+import static org.testng.Assert.assertFalse;
+import static org.testng.Assert.assertNotNull;
+import static org.testng.Assert.assertTrue;
+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}.
+ */
+public class ClickHouseSqlParserLoggingTest {
+
+    @Test(groups = { "unit" })
+    public void testParseFailureWarnDoesNotExposeSql() throws Exception {
+        String secret = "s3cret_db_" + System.nanoTime();
+        // A trailing identifier after USE <db> 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.
+        String rawError = null;
+        try {
+            new ClickHouseSqlParser(sql, null).sql();
+            fail("expected the invalid SQL to fail parsing");
+        } catch (Exception e) {
+            rawError = e.getMessage();
+        }
+        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);
+        }
+
+        // A parse failure degrades to a single fallback statement rather than throwing.
+        assertNotNull(stmts);
+        assertTrue(stmts.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);
+    }
+}