diff --git a/java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcResultSetLogger.java b/java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcResultSetLogger.java index 9d5531719f5d..2e5753fa2c46 100644 --- a/java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcResultSetLogger.java +++ b/java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcResultSetLogger.java @@ -22,36 +22,73 @@ import java.util.logging.LogRecord; /** - * Specialized high-performance logger for ResultSet and its related classes. Avoids expensive stack - * trace walking (caller inference) on hot-path logging calls. + * High-performance logging facade for ResultSet and its related classes. + * + *

This is deliberately not a {@link java.util.logging.Logger}. Every {@code Logger} + * instance registers itself as a child of its parent under a JVM-wide lock and that registration is + * never released, so a logger-per-ResultSet leaks. Instead, one real {@link + * BigQueryJdbcCustomLogger} is created per class and shared; this facade holds a reference to it + * plus the connection ID of the ResultSet it serves. + * + *

Hot-path methods ({@code finestTrace} etc.) set the source class and method explicitly, so no + * stack-trace walking (caller inference) happens for them. The connection ID is stamped into {@code + * LogRecord.getParameters()[0]} on every record so {@code PerConnectionFileHandler} can route the + * record even when the thread-local MDC (mapped diagnostic context — the per-thread connection ID + * set by the JDBC proxy) is empty, which is the normal case for un-proxied ResultSet calls. */ -public class BigQueryJdbcResultSetLogger extends BigQueryJdbcCustomLogger { - private static final ConcurrentHashMap cache = +public final class BigQueryJdbcResultSetLogger { + + /** One registered logger per class. Bounded by the number of result-set classes. */ + private static final ConcurrentHashMap DELEGATES = + new ConcurrentHashMap<>(); + + /** Facades with no connection ID are immutable and shared, matching the old caching behaviour. */ + private static final ConcurrentHashMap GLOBAL_FACADES = new ConcurrentHashMap<>(); + private final BigQueryJdbcCustomLogger delegate; private final String targetClassName; private final String connectionId; + private volatile BigQueryJdbcResultSetLogger arrowStructLogger; + private volatile BigQueryJdbcResultSetLogger jsonStructLogger; + private volatile BigQueryJdbcResultSetLogger arrowArrayLogger; + private volatile BigQueryJdbcResultSetLogger jsonArrayLogger; + + private BigQueryJdbcResultSetLogger( + BigQueryJdbcCustomLogger delegate, String targetClassName, String connectionId) { + this.delegate = delegate; + this.targetClassName = targetClassName; + this.connectionId = connectionId; + } + public static BigQueryJdbcResultSetLogger getLogger(Class clazz) { return getLogger(clazz, null); } public static BigQueryJdbcResultSetLogger getLogger(Class clazz, String connectionId) { + String className = clazz.getName(); + BigQueryJdbcCustomLogger delegate = + DELEGATES.computeIfAbsent(className, BigQueryJdbcCustomLogger::new); if (connectionId == null) { - return cache.computeIfAbsent( - clazz.getName(), k -> new BigQueryJdbcResultSetLogger(clazz, null)); + return GLOBAL_FACADES.computeIfAbsent( + className, k -> new BigQueryJdbcResultSetLogger(delegate, k, null)); } - return new BigQueryJdbcResultSetLogger(clazz, connectionId); + return new BigQueryJdbcResultSetLogger(delegate, className, connectionId); } public String getConnectionId() { return connectionId; } - private BigQueryJdbcResultSetLogger arrowStructLogger; - private BigQueryJdbcResultSetLogger jsonStructLogger; - private BigQueryJdbcResultSetLogger arrowArrayLogger; - private BigQueryJdbcResultSetLogger jsonArrayLogger; + /** The shared, registered logger this facade forwards to. Exposed for tests only. */ + BigQueryJdbcCustomLogger delegate() { + return delegate; + } + + public boolean isLoggable(Level level) { + return delegate.isLoggable(level); + } public BigQueryJdbcResultSetLogger getArrowStructLogger() { if (arrowStructLogger == null) { @@ -81,20 +118,13 @@ public BigQueryJdbcResultSetLogger getJsonArrayLogger() { return jsonArrayLogger; } - public BigQueryJdbcResultSetLogger(Class clazz) { - this(clazz, null); - } - - public BigQueryJdbcResultSetLogger(Class clazz, String connectionId) { - super(clazz.getName()); - this.targetClassName = clazz.getName(); - this.connectionId = connectionId; - } - - @Override + /** + * Stamps the connection ID into {@code params[0]} and forwards to the shared logger. Does not + * touch the record's source class/method: hot-path callers set them explicitly, and cold-path + * callers ({@code severe}, {@code warning}) rely on {@link + * BigQueryJdbcCustomLogger.BigQueryJdbcLogRecord} to infer them lazily. + */ public void log(LogRecord record) { - record.setSourceClassName(targetClassName); - record.setThreadID((int) Thread.currentThread().getId()); if (connectionId != null) { Object[] existingParams = record.getParameters(); if (existingParams == null || existingParams.length == 0) { @@ -106,93 +136,104 @@ public void log(LogRecord record) { record.setParameters(newParams); } } - super.log(record); + delegate.log(record); } private void logTrace(Level level, String methodName, String msg) { - if (isLoggable(level)) { - LogRecord record = new LogRecord(level, msg); - record.setSourceMethodName(methodName); - this.log(record); + if (!delegate.isLoggable(level)) { + return; } + LogRecord record = new LogRecord(level, msg); + record.setSourceClassName(targetClassName); + record.setSourceMethodName(methodName); + log(record); } private void logTrace(Level level, String methodName, Supplier msgSupplier) { - if (isLoggable(level)) { - LogRecord record = new LogRecord(level, msgSupplier.get()); - record.setSourceMethodName(methodName); - this.log(record); + if (!delegate.isLoggable(level)) { + return; } + logTrace(level, methodName, msgSupplier.get()); } - /** - * Log a message at Level.FINEST with predefined class name, method name and messageto avoid stack - * trace parsing on the hot-path. - */ + /** Cold path: builds a record whose caller is inferred lazily by the formatter. */ + private void logWithCaller(Level level, Throwable thrown, String msg) { + if (!delegate.isLoggable(level)) { + return; + } + LogRecord record = new BigQueryJdbcCustomLogger.BigQueryJdbcLogRecord(level, msg); + record.setThrown(thrown); + log(record); + } + + /** Log at FINEST with the class name, method name and "++enter++" preset (no stack walk). */ public void finestTrace(String methodName) { logTrace(Level.FINEST, methodName, "++enter++"); } - /** - * Log a message at Level.FINEST with predefined class name and method name to avoid stack trace - * parsing on the hot-path. - */ + /** Log at FINEST with the class name and method name preset (no stack walk). */ public void finestTrace(String methodName, String msg) { logTrace(Level.FINEST, methodName, msg); } - /** Log a lazy message at Level.FINEST with predefined class name and method name. */ + /** Log a lazy message at FINEST with the class name and method name preset. */ public void finestTrace(String methodName, Supplier msgSupplier) { logTrace(Level.FINEST, methodName, msgSupplier); } - /** Log a message at Level.FINER with predefined class name and method name. */ + /** Log at FINER with the class name and method name preset. */ public void finerTrace(String methodName, String msg) { logTrace(Level.FINER, methodName, msg); } - /** Log a lazy message at Level.FINER with predefined class name and method name. */ + /** Log a lazy message at FINER with the class name and method name preset. */ public void finerTrace(String methodName, Supplier msgSupplier) { logTrace(Level.FINER, methodName, msgSupplier); } - /** Log a message at Level.FINE with predefined class name and method name. */ + /** Log at FINE with the class name and method name preset. */ public void fineTrace(String methodName, String msg) { logTrace(Level.FINE, methodName, msg); } - /** Log a lazy message at Level.FINE with predefined class name and method name. */ + /** Log a lazy message at FINE with the class name and method name preset. */ public void fineTrace(String methodName, Supplier msgSupplier) { logTrace(Level.FINE, methodName, msgSupplier); } - @Override public void finest(String msg) { logTrace(Level.FINEST, "unknown", msg); } - @Override public void finest(Supplier msgSupplier) { logTrace(Level.FINEST, "unknown", msgSupplier); } - @Override public void finer(String msg) { logTrace(Level.FINER, "unknown", msg); } - @Override public void finer(Supplier msgSupplier) { logTrace(Level.FINER, "unknown", msgSupplier); } - @Override public void fine(String msg) { logTrace(Level.FINE, "unknown", msg); } - @Override public void fine(Supplier msgSupplier) { logTrace(Level.FINE, "unknown", msgSupplier); } + + public void warning(String format, Object... args) { + if (!delegate.isLoggable(Level.WARNING)) { + return; + } + String message = (args == null || args.length == 0) ? format : String.format(format, args); + logWithCaller(Level.WARNING, null, message); + } + + public void severe(String msg, Throwable thrown) { + logWithCaller(Level.SEVERE, thrown, msg); + } } diff --git a/java-bigquery-jdbc/src/test/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLoggerTest.java b/java-bigquery-jdbc/src/test/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLoggerTest.java index ab6fa432b770..d07052c07235 100644 --- a/java-bigquery-jdbc/src/test/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLoggerTest.java +++ b/java-bigquery-jdbc/src/test/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLoggerTest.java @@ -197,53 +197,60 @@ public void testLogWithException() { @Test public void testResultSetLoggerTrace() { BigQueryJdbcResultSetLogger rsLogger = - new BigQueryJdbcResultSetLogger(BigQueryBaseResultSet.class); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); TestHandler rsHandler = new TestHandler(); - rsLogger.addHandler(rsHandler); - rsLogger.setLevel(Level.ALL); + rsLogger.delegate().addHandler(rsHandler); + rsLogger.delegate().setLevel(Level.ALL); + try { - rsLogger.finestTrace("customMethod", "Hello finest trace message"); + rsLogger.finestTrace("customMethod", "Hello finest trace message"); - List records = rsHandler.getRecords(); - assertEquals(1, records.size()); - LogRecord record = records.get(0); + List records = rsHandler.getRecords(); + assertEquals(1, records.size()); + LogRecord record = records.get(0); - assertEquals(Level.FINEST, record.getLevel()); - assertEquals("customMethod", record.getSourceMethodName()); - assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); - assertEquals("Hello finest trace message", record.getMessage()); + assertEquals(Level.FINEST, record.getLevel()); + assertEquals("customMethod", record.getSourceMethodName()); + assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); + assertEquals("Hello finest trace message", record.getMessage()); + } finally { + rsLogger.delegate().removeHandler(rsHandler); + } } @Test public void testResultSetLoggerStandardMethods() { BigQueryJdbcResultSetLogger rsLogger = - new BigQueryJdbcResultSetLogger(BigQueryBaseResultSet.class); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); TestHandler rsHandler = new TestHandler(); - rsLogger.addHandler(rsHandler); - rsLogger.setLevel(Level.ALL); - - rsLogger.finest("Finest msg"); - rsLogger.finer("Finer msg"); - rsLogger.fine("Fine msg"); - - List records = rsHandler.getRecords(); - assertEquals(3, records.size()); - - LogRecord r1 = records.get(0); - assertEquals(Level.FINEST, r1.getLevel()); - assertEquals("unknown", r1.getSourceMethodName()); - assertEquals(BigQueryBaseResultSet.class.getName(), r1.getSourceClassName()); - assertEquals("Finest msg", r1.getMessage()); - - LogRecord r2 = records.get(1); - assertEquals(Level.FINER, r2.getLevel()); - assertEquals("unknown", r2.getSourceMethodName()); - assertEquals("Finer msg", r2.getMessage()); - - LogRecord r3 = records.get(2); - assertEquals(Level.FINE, r3.getLevel()); - assertEquals("unknown", r3.getSourceMethodName()); - assertEquals("Fine msg", r3.getMessage()); + rsLogger.delegate().addHandler(rsHandler); + rsLogger.delegate().setLevel(Level.ALL); + try { + rsLogger.finest("Finest msg"); + rsLogger.finer("Finer msg"); + rsLogger.fine("Fine msg"); + + List records = rsHandler.getRecords(); + assertEquals(3, records.size()); + + LogRecord r1 = records.get(0); + assertEquals(Level.FINEST, r1.getLevel()); + assertEquals("unknown", r1.getSourceMethodName()); + assertEquals(BigQueryBaseResultSet.class.getName(), r1.getSourceClassName()); + assertEquals("Finest msg", r1.getMessage()); + + LogRecord r2 = records.get(1); + assertEquals(Level.FINER, r2.getLevel()); + assertEquals("unknown", r2.getSourceMethodName()); + assertEquals("Finer msg", r2.getMessage()); + + LogRecord r3 = records.get(2); + assertEquals(Level.FINE, r3.getLevel()); + assertEquals("unknown", r3.getSourceMethodName()); + assertEquals("Fine msg", r3.getMessage()); + } finally { + rsLogger.delegate().removeHandler(rsHandler); + } } @Test @@ -263,21 +270,24 @@ public void testCustomLoggerSupplierMethods() { @Test public void testResultSetLoggerSupplierMethods() { BigQueryJdbcResultSetLogger rsLogger = - new BigQueryJdbcResultSetLogger(BigQueryBaseResultSet.class); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); TestHandler rsHandler = new TestHandler(); - rsLogger.addHandler(rsHandler); - rsLogger.setLevel(Level.ALL); - - rsLogger.finest(() -> "Lazy finest RS message"); + rsLogger.delegate().addHandler(rsHandler); + rsLogger.delegate().setLevel(Level.ALL); + try { + rsLogger.finest(() -> "Lazy finest RS message"); - List records = rsHandler.getRecords(); - assertEquals(1, records.size()); - LogRecord record = records.get(0); + List records = rsHandler.getRecords(); + assertEquals(1, records.size()); + LogRecord record = records.get(0); - assertEquals(Level.FINEST, record.getLevel()); - assertEquals("unknown", record.getSourceMethodName()); - assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); - assertEquals("Lazy finest RS message", record.getMessage()); + assertEquals(Level.FINEST, record.getLevel()); + assertEquals("unknown", record.getSourceMethodName()); + assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); + assertEquals("Lazy finest RS message", record.getMessage()); + } finally { + rsLogger.delegate().removeHandler(rsHandler); + } } @Test @@ -298,60 +308,70 @@ public void testSupplierNotEvaluatedWhenDisabled() { @Test public void testResultSetLoggerSupplierTraceMethods() { BigQueryJdbcResultSetLogger rsLogger = - new BigQueryJdbcResultSetLogger(BigQueryBaseResultSet.class); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); TestHandler rsHandler = new TestHandler(); - rsLogger.addHandler(rsHandler); - rsLogger.setLevel(Level.ALL); - - rsLogger.finestTrace("customTraceMethod", () -> "Lazy finest RS trace message"); + rsLogger.delegate().addHandler(rsHandler); + rsLogger.delegate().setLevel(Level.ALL); + try { + rsLogger.finestTrace("customTraceMethod", () -> "Lazy finest RS trace message"); - List records = rsHandler.getRecords(); - assertEquals(1, records.size()); - LogRecord record = records.get(0); + List records = rsHandler.getRecords(); + assertEquals(1, records.size()); + LogRecord record = records.get(0); - assertEquals(Level.FINEST, record.getLevel()); - assertEquals("customTraceMethod", record.getSourceMethodName()); - assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); - assertEquals("Lazy finest RS trace message", record.getMessage()); + assertEquals(Level.FINEST, record.getLevel()); + assertEquals("customTraceMethod", record.getSourceMethodName()); + assertEquals(BigQueryBaseResultSet.class.getName(), record.getSourceClassName()); + assertEquals("Lazy finest RS trace message", record.getMessage()); + } finally { + rsLogger.delegate().removeHandler(rsHandler); + } } @Test public void testResultSetLoggerCachingBehavior() { - // Global logger (connectionId is null) should be cached + // Global facades (no connection ID) are shared. BigQueryJdbcResultSetLogger globalLogger1 = BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); BigQueryJdbcResultSetLogger globalLogger2 = BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class); assertSame(globalLogger1, globalLogger2); - - // Connection-specific loggers should not be cached globally + // Connection-scoped facades are distinct lightweight objects, but they all forward to the + // single registered logger for the class — that is what prevents the registration leak. BigQueryJdbcResultSetLogger connLogger1 = BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class, "conn-123"); BigQueryJdbcResultSetLogger connLogger2 = - BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class, "conn-123"); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class, "conn-456"); assertNotSame(connLogger1, connLogger2); + assertSame(connLogger1.delegate(), connLogger2.delegate()); + assertSame(globalLogger1.delegate(), connLogger1.delegate()); } @Test public void testResultSetLoggerParameterPreservation() { BigQueryJdbcResultSetLogger rsLogger = - new BigQueryJdbcResultSetLogger(BigQueryBaseResultSet.class, "conn-123"); + BigQueryJdbcResultSetLogger.getLogger(BigQueryBaseResultSet.class, "conn-123"); TestHandler rsHandler = new TestHandler(); - rsLogger.addHandler(rsHandler); - rsLogger.setLevel(Level.ALL); + rsLogger.delegate().addHandler(rsHandler); + rsLogger.delegate().setLevel(Level.ALL); - LogRecord record = new LogRecord(Level.INFO, "Processing job {0}"); - record.setParameters(new Object[] {"job-999"}); - rsLogger.log(record); + try { - List records = rsHandler.getRecords(); - assertEquals(1, records.size()); - LogRecord loggedRecord = records.get(0); + LogRecord record = new LogRecord(Level.INFO, "Processing job {0}"); + record.setParameters(new Object[] {"job-999"}); + rsLogger.log(record); + + List records = rsHandler.getRecords(); + assertEquals(1, records.size()); + LogRecord loggedRecord = records.get(0); - Object[] params = loggedRecord.getParameters(); - assertEquals(2, params.length); - assertEquals("conn-123", params[0]); - assertEquals("job-999", params[1]); + Object[] params = loggedRecord.getParameters(); + assertEquals(2, params.length); + assertEquals("conn-123", params[0]); + assertEquals("job-999", params[1]); + } finally { + rsLogger.delegate().removeHandler(rsHandler); + } } private void assertConnectionIdPropagated( @@ -360,7 +380,7 @@ private void assertConnectionIdPropagated( String expectedMessage, Runnable action) { Level originalRootLevel = BigQueryJdbcRootLogger.getRootLogger().getLevel(); - Level originalLoggerLevel = logger.getLevel(); + Level originalLoggerLevel = logger.delegate().getLevel(); Map originalHandlerLevels = new HashMap<>(); for (Handler h : BigQueryJdbcRootLogger.getRootLogger().getHandlers()) { originalHandlerLevels.put(h, h.getLevel()); @@ -368,7 +388,7 @@ private void assertConnectionIdPropagated( } BigQueryJdbcRootLogger.getRootLogger().setLevel(Level.ALL); - logger.setLevel(Level.ALL); + logger.delegate().setLevel(Level.ALL); try { capturedLogs.clear(); @@ -378,7 +398,7 @@ private void assertConnectionIdPropagated( assertTrue(assertLogContains(expectedMessage)); } finally { BigQueryJdbcRootLogger.getRootLogger().setLevel(originalRootLevel); - logger.setLevel(originalLoggerLevel); + logger.delegate().setLevel(originalLoggerLevel); for (Entry entry : originalHandlerLevels.entrySet()) { entry.getKey().setLevel(entry.getValue()); } @@ -638,6 +658,28 @@ public void testCreatingDatabaseMetaDataDoesNotRegisterChildLoggers() + " root logger"); } + @Test + public void testConnectionScopedResultSetLoggersDoNotRegisterChildLoggers() + throws ReflectiveOperationException { + Logger rootLogger = BigQueryJdbcRootLogger.getRootLogger(); + // Warm up so the per-class delegates (and their one-time registration) exist before measuring. + BigQueryJdbcResultSetLogger.getLogger(BigQueryArrowResultSet.class, "warm-up") + .getArrowStructLogger() + .getArrowArrayLogger(); + int childrenBefore = childLoggerCount(rootLogger); + + for (int i = 0; i < OBJECT_COUNT; i++) { + BigQueryJdbcResultSetLogger.getLogger(BigQueryArrowResultSet.class, "conn-" + i) + .getArrowStructLogger() + .getArrowArrayLogger(); + } + + assertEquals( + childrenBefore, + childLoggerCount(rootLogger), + "Connection-scoped result-set loggers must not register child loggers on the driver root"); + } + /** * Reads the JDK-internal {@code Logger.kids} list. This field is private to {@code java.logging}, * so the surefire {@code argLine} opens {@code java.util.logging} to the test classpath.