[client-v2, jdbc-v2] Fix bad and noisy logging (#2970) - #2973
[client-v2, jdbc-v2] Fix bad and noisy logging (#2970)#2973polyglotAI-bot wants to merge 10 commits into
Conversation
- Parser no longer logs the full user SQL at WARN (can contain passwords/PII); the failure warns without the statement and the SQL is logged only at DEBUG. - jdbc-v2 metadata unknown-type fallbacks (mapping to JDBCType.OTHER) log at DEBUG instead of ERROR, and use the com.clickhouse.logging %s format so the type name actually renders. - Remove the per-conversion DEBUG stack trace in ExceptionUtils.toSqlState (often contained SQL) and the now-unused slf4j logger field. - Remove the per-element TRACE in PreparedStatement parameter encoding and the two duplicate per-execution SQL TRACEs (the query is still traced once). - Consolidate client-v2 retry logging into a single WARN carrying operation, attempt, endpoint, query id and cause; downgrade the duplicate transport connection-failure WARNs to DEBUG so a retried failure is not double-logged. - Remove the two redundant per-operation compression DEBUGs (already logged at init) and the jdbc-v2 driver static-init banner. - LZ4 in/out stream logs now report the algorithm and buffer size instead of an unusable object identity. Fixes: #2970
Client V2 CoverageCoverage Report
Class Coverage
|
JDBC V2 CoverageCoverage Report
Class Coverage
|
JDBC V1 CoverageCoverage Report
Class Coverage
|
Client V1 CoverageCoverage Report
Class Coverage
|
chernser
left a comment
There was a problem hiding this comment.
slf4j use {} for place holder value. correct, please
I've left comments.
…ing-2970 # Conflicts: # CHANGELOG.md
…SLF4J @chernser asked for SLF4J `{}` placeholders on DatabaseMetaDataImpl and ClickHouseSqlParser. Those two classes used the deprecated `com.clickhouse.logging.Logger` facade, which formats via `java.util.Formatter` (`%s`), so a bare `%s`->`{}` swap would have rendered a literal `{}`. Migrate both classes to `org.slf4j.Logger`/`LoggerFactory` (matching the rest of jdbc-v2) and switch the placeholders to `{}`, so they render correctly. This also fixes a pre-existing latent bug: DatabaseMetaData.getTables logged `catalog={}, schemaPattern={}, ...` literally under the old facade. Added a regression test that captures the getTables DEBUG line and asserts the placeholders are substituted.
|
Thanks @chernser. You're right that these should use SLF4J So rather than just changing the placeholder, I migrated both classes to Added a regression test — Pushed in 3e493d7. I also merged |
…cleanup Consolidate the three byte-identical retry warnings in Client.insert/query into a single logRetryAndSelectNextNode(...) helper with a per-operation label. The retry is now logged in exactly one place and the previously duplicated new lines become textually distinct, clearing the new-code duplication SonarCloud flagged. Add DatabaseMetaDataImplMutatorTest covering the unknown/null type-name fallback to JDBCType.OTHER in the getColumns and getTypeInfo result-set mutators, so the DEBUG fallback logs (previously uncovered new lines) are exercised and new-code coverage is restored. No behaviour change: the retry branch still logs then advances to the next node, and unresolved type names still degrade to JDBCType.OTHER.
…ing-2970 # Conflicts: # CHANGELOG.md
|
Addressed the SonarCloud new-code Quality Gate (was failing on coverage 63.6% and duplication 6.25% after the last rebase shrank the new-code window):
Also merged latest |
…overage
testGetTablesDebugSubstitutesPlaceholders captured System.err and asserted the
getTables DEBUG line substituted its {} placeholders. It relied on
simplelogger.properties enabling DEBUG for com.clickhouse.jdbc, but the Coverage
workflow (analysis.yml) deletes simplelogger.* before `mvn -Pcoverage verify`, so
DEBUG was off, nothing was captured, and the assertion failed. That single
failsafe failure aborted the jdbc-v2 module before jacoco-merge/jacoco-aggregate
ran, so SonarCloud saw no coverage for any jdbc-v2 file and the new-code coverage
gate failed (71.4%).
Pin the SLF4J migration deterministically by asserting the class logger is an
org.slf4j.Logger (the old com.clickhouse.logging facade rendered {} literally),
and only attempt the System.err capture when DEBUG is actually enabled. The
module now builds under coverage, so the existing DatabaseMetaDataImplMutatorTest
unit coverage of the debug fallback lines is reported.
SonarCloud new-code coverage gate — root cause & fix (
|
|
@cursor review |
There was a problem hiding this comment.
✅ Bugbot reviewed your changes and found no new issues!
Comment @cursor review or bugbot run to trigger another review on this PR
Reviewed by Cursor Bugbot for commit 6fb6546. Configure here.
There was a problem hiding this comment.
Pull request overview
This PR reduces noisy/mis-levelled logging and mitigates accidental SQL/PII leakage in jdbc-v2 and client-v2, primarily by adjusting log levels/content and consolidating retry logging.
Changes:
- Migrates
jdbc-v2ClickHouseSqlParserandDatabaseMetaDataImpllogging to SLF4J and removes/downgrades noisy logs (including unknown-type metadata fallbacks). - Consolidates retry logging in
client-v2and removes redundant/hot-path compression and parameter-encoding trace logs. - Updates LZ4 stream logs to be more actionable, and adds regression/unit tests plus a
CHANGELOGentry.
Reviewed changes
Copilot reviewed 14 out of 14 changed files in this pull request and generated 3 comments.
Show a summary per file
| File | Description |
|---|---|
| jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataTest.java | Adds a regression test intended to pin SLF4J placeholder substitution behavior. |
| jdbc-v2/src/test/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImplMutatorTest.java | Adds unit tests pinning unknown/null type-name fallback to JDBCType.OTHER. |
| jdbc-v2/src/main/javacc/ClickHouseSqlParser.jj | Stops logging full SQL at WARN on parse failure; moves statement logging to DEBUG and migrates to SLF4J. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/StatementImpl.java | Removes duplicate per-execution TRACE SQL logs in escape parsing. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/PreparedStatementImpl.java | Removes per-object TRACE logging during parameter encoding. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/metadata/DatabaseMetaDataImpl.java | Downgrades unknown-type fallback logs from ERROR to DEBUG; migrates to SLF4J placeholder formatting. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/internal/ExceptionUtils.java | Removes per-conversion DEBUG stack trace logging from SQL-state conversion. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/Driver.java | Removes static-init driver banner/version DEBUG logs. |
| jdbc-v2/src/main/java/com/clickhouse/jdbc/ConnectionImpl.java | Removes “framework detection disabled” DEBUG log by simplifying the conditional. |
| client-v2/src/main/java/com/clickhouse/client/api/internal/HttpAPIClientHelper.java | Downgrades transport connection WARNs to DEBUG and removes per-request compression DEBUG logs. |
| client-v2/src/main/java/com/clickhouse/client/api/internal/ClickHouseLZ4OutputStream.java | Makes constructor DEBUG log actionable (buffer size) instead of object identity. |
| client-v2/src/main/java/com/clickhouse/client/api/internal/ClickHouseLZ4InputStream.java | Makes constructor DEBUG log actionable; removes DEBUG in buffer reallocation branch. |
| client-v2/src/main/java/com/clickhouse/client/api/Client.java | Consolidates retry logging into a single helper and removes duplicate “Retrying.” WARN+stack logging. |
| CHANGELOG.md | Adds a Bug Fixes entry describing the logging changes and their motivation. |
…e class - ClickHouseSqlParser: the parse-failure WARN no longer includes the parser exception message (a JavaCC parse error embeds offending SQL token text, so it could expose credentials/PII). WARN is now a generic message; the raw SQL and the parse exception are logged only at DEBUG (throwable attached). Fixed the "Github" -> "GitHub" wording. - Client.logRetryAndSelectNextNode: the consolidated retry WARN now names the failure cause's exception class in addition to its message, so it stays informative when getMessage() is null (still no stack trace attached). - DatabaseMetaDataTest: the getTables SLF4J-substitution assertions only run when System.err capture actually produced output; the logger-facade assertion remains the deterministic regression guard. - Added regression tests: ClickHouseSqlParserLoggingTest (a parse-failure WARN must not expose the SQL or the parser error) and ClientFailoverUnitTest.testRetryWarnNamesExceptionClass.
Pins that a parse failure does not expose the SQL statement or the parser error detail at WARN. Placed in com.clickhouse.jdbc.internal (the parser package com.clickhouse.jdbc.internal.parser.javacc is .gitignored for generated sources).
|
Addressed the Copilot review on d87463c (2 commits atop 6fb6546):
Both new tests were verified to fail on the unpatched code and pass with the fix; |
|
@cursor review |
There was a problem hiding this comment.
✅ Bugbot reviewed your changes and found no new issues!
Comment @cursor review or bugbot run to trigger another review on this PR
Reviewed by Cursor Bugbot for commit d87463c. Configure here.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 16 out of 16 changed files in this pull request and generated no new comments.
Comments suppressed due to low confidence (2)
jdbc-v2/src/test/java/com/clickhouse/jdbc/internal/ClickHouseSqlParserLoggingTest.java:66
- This test relies on capturing SLF4J SimpleLogger output by temporarily redirecting
System.err, but SimpleLogger can cache the outputPrintStreamat logger initialization time. SinceClickHouseSqlParseris already referenced earlier in the test, the WARN may be written to the originalSystem.err, leavingwarnempty and failing the assertion even though the WARN was actually emitted. Consider making the runtime capture best-effort (skip only when capture produced no output), similar to the guard used inDatabaseMetaDataTest.
assertFalse(warn.isEmpty(), "expected a parse-failure WARN to be emitted");
client-v2/src/test/java/com/clickhouse/client/api/ClientFailoverUnitTest.java:77
- This test captures logs by redirecting
System.err, but SLF4J SimpleLogger may cache the output stream when the logger is first initialized. IfClientlogging was initialized earlier (e.g., by another test in the same JVM), the WARN will go to the originalSystem.errandwarnwill be empty, causing a false failure. Add a guard to skip the assertion only when the capture itself produced no output.
Assert.assertFalse(warn.isEmpty(),
"expected a consolidated retry WARN to be emitted:\n" + captured.toString("UTF-8"));
|
Thanks @copilot — I looked into both suppressed items (the 1. slf4j-simple here does not cache 2. Reproduced the exact scenario; the capture works. I ran a throwaway probe that initializes the logger + slf4j-simple config against the original 3. The 4. Why the assertions stay strict. Happy to switch to the best-effort pattern if you'd prefer it for consistency. |
chernser
left a comment
There was a problem hiding this comment.
- fix places where placeholder '{}' used along with Exception in parameters - this should be done with string concat
- see comments
… +1 into helper Per @chernser's review on #2973: - SLF4J placeholders do not bind a Throwable passed as an argument (that is a separate (String, Throwable) overload), so the log sites that pass an exception alongside {} now use string concatenation with the throwable as the trailing argument: ClickHouseSqlParser parse-failure DEBUG and the two DatabaseMetaDataImpl unknown-type DEBUG fallbacks (getColumns / getTypeInfo). The one remaining {} site with no exception argument is left as-is. - Moved the display '+1' arithmetic (1-based attempt, total attempts) out of the three retry call sites and into logRetryAndSelectNextNode; the emitted WARN is unchanged. Strengthened ClientFailoverUnitTest to pin 'attempt 1 of 3'.
|
Thanks @chernser — addressed all three points in
Note: merging |
|



Description
Fixes #2970.
Addresses the bad/noisy logging defects reported in
jdbc-v2andclient-v2. The lead item is a security/privacy concern:ClickHouseSqlParserlogged the entire user SQL atWARNon a parse failure, so a statement such asCREATE USER ... IDENTIFIED BY '...'leaked the password/PII into logs. The rest are mis-levelled logs (per-rowERRORwhile gracefully falling back), redundant/duplicate logs, and logs that emit an unusable object identity. Each change is a level/content/redundancy fix on a live logging path — no runtime behavior, control flow, exception type, or public API changes.Changes
jdbc-v2/.../javacc/ClickHouseSqlParser.jj. A parse failure now warns without the statement; the raw SQL is logged only atDEBUG(opt-in). (loghere iscom.clickhouse.logging.Logger, so%sis used.)jdbc-v2/.../metadata/DatabaseMetaDataImpl.java. The three sites that loggedERRORper unknown-type row while successfully falling back toJDBCType.OTHERnow log atDEBUG. This class also usescom.clickhouse.logging.Logger, so the messages were switched to its%sformat — previously two used string concatenation and one used a literal{}that never substituted, so the type name now actually renders.jdbc-v2/.../internal/ExceptionUtils.java.toSqlStateno longer emits aDEBUGstack trace (frequently containing SQL) on every JDBC exception conversion; the now-unused slf4j logger field and imports were removed.PreparedStatementImpl.java,StatementImpl.java. Removed the recursive per-elementTRACEin parameter encoding, and the two duplicate per-execution SQLTRACEs inparseJdbcEscapeSyntax(each execution still traces the SQL query once at its call site).client-v2/.../Client.java+HttpAPIClientHelper.java. A retried request failure was logged twice: once by the transport (WARN) and again as a bare"Retrying."WARNwith a full stack. It is now a single consolidated retryWARNcarrying operation, attempt, endpoint, query id and cause; the duplicate transport connection-failureWARNs (UnknownHostException,ConnectException/NoRouteToHostException) were downgraded toDEBUG(the failure is still fully available in the thrown exception chain and the existing transportDEBUG).DEBUG—HttpAPIClientHelper.java. Removed the twoDEBUGs emitted on every request/response (wrapRequestEntity/wrapResponseEntity); compression settings are already logged once at client initialization.jdbc-v2/.../Driver.java. Removed the static-init"Initializing ... V2"/ version banner (the version is reachable through the JDBC API).ClickHouseLZ4InputStream.java,ClickHouseLZ4OutputStream.java. The constructor logs now report the algorithm and buffer size instead of an object identity (LZ4Decompressor@1a2b); removed theDEBUGinside the decompression buffer-reallocation branch.CHANGELOG.md— Bug Fixes entry.Test
These are logging-only changes with no runtime-observable behavior (no return value, exception, or control-flow change), so there is no meaningful behavioral assertion to add. In line with the repo's "don't pad coverage" guidance — and because
client-v2/jdbc-v2useslf4j-simplein test scope (no programmatic log capture) — they are covered by inspection, a clean build, and theCHANGELOG, rather than a fragile log-capture harness.Verification performed:
mvn -pl client-v2,jdbc-v2 -am -DskipTests install— BUILD SUCCESS (main + test sources compile; the JavaCC parser regenerates cleanly from the.jjchange).mvn -pl jdbc-v2 -Dtest=JavaCCParserTest test— 382/382 pass, confirming the regenerated parser (the only change with codegen risk) still parses correctly.docs/changes_checklist.mdwalkthrough — "Logging added or changed"ERROR→DEBUG; a retried, about-to-be-retried transport failure isWARNonce (wasWARN×2); transport failures that are rethrown to the caller areDEBUG(the caller owns the error).TRACEand the per-HTTP-operation compressionDEBUGs; the retryWARNfires once per attempt, not once per layer.WARNnames operation/attempt/endpoint/query id/cause.WARN; the per-conversion stack trace (often SQL) removed.com.clickhouse.loggingcaptures it; slf4j attaches it). The retryWARNintentionally carries the concise cause message rather than a full stack per attempt — the full stack remains in the thrown exception chain and the transportDEBUG— to avoid turning one failure into many noisy stack dumps."..." + typeNameconcatenation now use parameterized%s.No public API signature, output format, default, or retry behavior changes, so
docs/features.mdis unaffected.Pre-PR validation gate
AGENTS.md/docs/changes_checklist.md(Logging section walked through above)Note for reviewers
Kept scoped to bad/excessive logging per the issue; sibling issues #2969 (missing logs) and #2968 (logging bugs, addressed separately in #2971) are intentionally out of scope. #2971 touches
HttpAPIClientHelper.java/StatementImpl.java/CHANGELOG.mdin different regions — aCHANGELOG.mdtop-of-section conflict between the two PRs is expected and trivially resolved by keeping both entries.