SNOW-3411804: proper logging for auto-config related messages with Easy Logging and the config key provenance added in 2625 (#2632)

Author: sfc-gh-dszmolka

CHANGELOG.md

@@ -10,6 +10,7 @@
       - Enhancement: now parameters passed as `Properties()` are also considered when building connection. For conflicting items defined in multiple places, priority is: Properties > JDBC URL > `connections.toml`
       - Enhancement (supportability): added provenance tracking for config keys and log them once per connection on debug level
     - Fixed IllegalStateException when creating new Snowflake connections during JVM shutdown (SIGTERM); HeartbeatRegistry now skips heartbeat registration gracefully instead of throwing (snowflakedb/snowflake-jdbc#2617).
+    - Fixed auto-config debug log messages (provenance, TOML parsing) not appearing in `client_config_file`-governed log file; messages are now replayed after logger initialization so they reach the FileHandler (snowflakedb/snowflake-jdbc#2632).
 
 - v4.2.0
     - Extended the `SKIP_TOKEN_FILE_PERMISSIONS_VERIFICATION` environment variable to also bypass permission verification on the `connections.toml` config file and on the credential cache file (`credential_cache_v1.json`), unblocking driver use in SPCS environments where strict 0600/0700 ownership cannot be guaranteed (snowflakedb/snowflake-jdbc#2614)

src/main/java/net/snowflake/client/internal/config/ConnectionParameters.java

@@ -1,10 +1,13 @@
 package net.snowflake.client.internal.config;
 
+import java.util.ArrayList;
+import java.util.List;
 import java.util.Properties;
 
 public class ConnectionParameters {
   private final String url;
   private final Properties params;
+  private final List<String> deferredLogMessages = new ArrayList<>();
 
   public ConnectionParameters(String uri, Properties params) {
     this.url = uri;
@@ -18,4 +21,12 @@ public String getUrl() {
   public Properties getParams() {
     return params;
   }
+
+  public void addDeferredLogMessage(String message) {
+    deferredLogMessages.add(message);
+  }
+
+  public List<String> getDeferredLogMessages() {
+    return deferredLogMessages;
+  }
 }

src/main/java/net/snowflake/client/internal/config/SFConnectionConfigParser.java

@@ -51,24 +51,32 @@ public class SFConnectionConfigParser {
 
   public static ConnectionParameters buildConnectionParameters(String connectionUrl)
       throws SnowflakeSQLException {
-    return buildConnectionParameters(connectionUrl, new HashMap<>());
+    return buildConnectionParameters(connectionUrl, new HashMap<>(), null);
   }
 
   /**
    * Build connection parameters from URL and TOML file, optionally tracking provenance. When
-   * provenance is non-null, each key's source ("TOML" or "URL") is recorded as it is resolved.
+   * provenance is non-null, each key's source ("TOML" or "URL") is recorded as it is resolved. When
+   * deferredMessages is non-null, debug log messages are also buffered for later replay.
    */
   public static ConnectionParameters buildConnectionParameters(
-      String connectionUrl, Map<String, String> provenance) throws SnowflakeSQLException {
+      String connectionUrl, Map<String, String> provenance, List<String> deferredMessages)
+      throws SnowflakeSQLException {
     Map<String, String> urlParameters = parseAutoConfigJdbcUrlParameters(connectionUrl);
     String defaultConnectionName = urlParameters.get("connectionName");
     if (isBlank(defaultConnectionName)) {
       defaultConnectionName =
           Optional.ofNullable(systemGetEnv(SNOWFLAKE_DEFAULT_CONNECTION_NAME_KEY)).orElse(DEFAULT);
     }
-    logger.debug("Attempting to load the configuration {} from toml file.", defaultConnectionName);
+    String attemptMsg =
+        String.format(
+            "Attempting to load the configuration %s from toml file.", defaultConnectionName);
+    logger.debug(attemptMsg);
+    if (deferredMessages != null) {
+      deferredMessages.add(attemptMsg);
+    }
     Map<String, String> fileConnectionConfiguration =
-        loadDefaultConnectionConfiguration(defaultConnectionName);
+        loadDefaultConnectionConfiguration(defaultConnectionName, deferredMessages);
 
     if (fileConnectionConfiguration != null && !fileConnectionConfiguration.isEmpty()) {
       if (provenance != null) {
@@ -88,7 +96,12 @@ public static ConnectionParameters buildConnectionParameters(
       connectionProperties.putAll(fileConnectionConfiguration);
 
       String url = createUrl(fileConnectionConfiguration);
-      logger.debug("Url created using parameters from connection configuration file: {}", url);
+      String urlMsg =
+          String.format("Url created using parameters from connection configuration file: %s", url);
+      logger.debug(urlMsg);
+      if (deferredMessages != null) {
+        deferredMessages.add(urlMsg);
+      }
 
       if ("oauth".equals(fileConnectionConfiguration.get("authenticator"))
           && fileConnectionConfiguration.get("token") == null) {
@@ -177,7 +190,7 @@ private static void mergeUrlParametersIntoConfiguration(
   }
 
   private static Map<String, String> loadDefaultConnectionConfiguration(
-      String defaultConnectionName) throws SnowflakeSQLException {
+      String defaultConnectionName, List<String> deferredMessages) throws SnowflakeSQLException {
     String configDirectory = systemGetEnv(SNOWFLAKE_HOME_KEY);
     if (configDirectory == null) {
       String homeDir = systemGetProperty("user.home");
@@ -190,18 +203,33 @@ private static Map<String, String> loadDefaultConnectionConfiguration(
     Path configFilePath = Paths.get(configDirectory, "connections.toml");
 
     if (Files.exists(configFilePath)) {
-      logger.debug(
-          "Reading connection parameters from file {} using key: {}",
-          configFilePath,
-          defaultConnectionName);
+      String readMsg =
+          String.format(
+              "Reading connection parameters from file %s using key: %s",
+              configFilePath, defaultConnectionName);
+      logger.debug(readMsg);
+      if (deferredMessages != null) {
+        deferredMessages.add(readMsg);
+      }
       Map<String, Map> parametersMap = readParametersMap(configFilePath);
       Map<String, String> defaultConnectionParametersMap = parametersMap.get(defaultConnectionName);
       if (defaultConnectionParametersMap == null) {
-        logger.debug("The Connection {} not found in connections.toml.", defaultConnectionName);
+        String notFoundMsg =
+            String.format(
+                "The Connection %s not found in connections.toml.", defaultConnectionName);
+        logger.debug(notFoundMsg);
+        if (deferredMessages != null) {
+          deferredMessages.add(notFoundMsg);
+        }
         throw new SnowflakeSQLException(
             "The Connection " + defaultConnectionName + " not found in connections.toml file.");
       } else {
-        logger.debug("The Connection {} found in connections.toml.", defaultConnectionName);
+        String foundMsg =
+            String.format("The Connection %s found in connections.toml.", defaultConnectionName);
+        logger.debug(foundMsg);
+        if (deferredMessages != null) {
+          deferredMessages.add(foundMsg);
+        }
       }
       return defaultConnectionParametersMap;
     } else {

src/main/java/net/snowflake/client/internal/driver/AutoConfigurationHelper.java

@@ -1,9 +1,12 @@
 package net.snowflake.client.internal.driver;
 
+import java.util.ArrayList;
 import java.util.HashMap;
+import java.util.List;
 import java.util.Map;
 import java.util.Properties;
 import java.util.StringJoiner;
+import java.util.TreeMap;
 import net.snowflake.client.api.exception.SnowflakeSQLException;
 import net.snowflake.client.internal.config.ConnectionParameters;
 import net.snowflake.client.internal.config.SFConnectionConfigParser;
@@ -63,17 +66,30 @@ public static boolean isAutoConfigurationUrl(String url) {
    * @return ConnectionParameters with resolved configuration
    * @throws SnowflakeSQLException if auto-configuration is requested but fails
    */
+  /**
+   * Internal key used by ConnectionFactory to carry deferred log messages on the Properties object.
+   * The value is a {@code List<String>} (not a String), so it won't interfere with session property
+   * parsing. ConnectionParameters is discarded before reaching DefaultSFConnectionHandler, so
+   * ConnectionFactory transfers the messages onto Properties which does flow through.
+   */
+  public static final String DEFERRED_LOG_MESSAGES_KEY = "_snowflake.internal.deferredLogMessages";
+
   public static ConnectionParameters resolveConnectionParameters(String url, Properties info)
       throws SnowflakeSQLException {
 
     if (isAutoConfigurationUrl(url)) {
-      logger.debug(
-          "JDBC connection initializing with URL '{}'. Autoconfiguration is enabled.",
-          AUTO_CONNECTION_PREFIX);
+      List<String> deferredMessages = new ArrayList<>();
+
+      String initMsg =
+          String.format(
+              "JDBC connection initializing with URL '%s'. Autoconfiguration is enabled.",
+              AUTO_CONNECTION_PREFIX);
+      logger.debug(initMsg);
+      deferredMessages.add(initMsg);
 
       Map<String, String> provenance = new HashMap<>();
       ConnectionParameters params =
-          SFConnectionConfigParser.buildConnectionParameters(url, provenance);
+          SFConnectionConfigParser.buildConnectionParameters(url, provenance, deferredMessages);
       if (params == null) {
         throw new SnowflakeSQLException(
             "Unavailable connection configuration parameters expected for "
@@ -89,7 +105,11 @@ public static ConnectionParameters resolveConnectionParameters(String url, Prope
         }
       }
 
-      logAutoConfigProvenance(provenance);
+      logAutoConfigProvenance(provenance, deferredMessages);
+
+      for (String msg : deferredMessages) {
+        params.addDeferredLogMessage(msg);
+      }
 
       return params;
     } else {
@@ -132,15 +152,18 @@ private static void mergeInfoPropertiesIntoParams(
 
   // Only covers the jdbc:snowflake:auto path. The standard jdbc:snowflake:// path merges
   // URL+Properties in SnowflakeConnectString.parse without provenance tracking.
-  private static void logAutoConfigProvenance(Map<String, String> provenance) {
-    if (!logger.isDebugEnabled()) {
-      return;
-    }
+  private static void logAutoConfigProvenance(
+      Map<String, String> provenance, List<String> deferredMessages) {
     StringJoiner sj = new StringJoiner(", ");
-    for (Map.Entry<String, String> entry : provenance.entrySet()) {
+    for (Map.Entry<String, String> entry : new TreeMap<>(provenance).entrySet()) {
       sj.add(entry.getKey() + "(" + entry.getValue() + ")");
     }
-    logger.debug("Auto-configuration resolved properties: [{}]", sj.toString());
+    String provenanceMsg =
+        String.format("Auto-configuration resolved properties: [%s]", sj.toString());
+    logger.debug(provenanceMsg);
+    if (deferredMessages != null) {
+      deferredMessages.add(provenanceMsg);
+    }
     provenance.clear();
   }
 }

src/main/java/net/snowflake/client/internal/driver/ConnectionFactory.java

@@ -2,6 +2,7 @@
 
 import java.sql.Connection;
 import java.sql.SQLException;
+import java.util.List;
 import java.util.Properties;
 import net.snowflake.client.api.exception.SnowflakeSQLException;
 import net.snowflake.client.internal.api.implementation.connection.SnowflakeConnectionImpl;
@@ -59,6 +60,13 @@ public static Connection createConnection(String url, Properties info) throws SQ
       throw new SnowflakeSQLException("Connection string is invalid. Unable to parse.");
     }
 
+    // Transfer deferred log messages from ConnectionParameters to Properties so they survive
+    // into DefaultSFConnectionHandler.initialize() for replay after initLogger().
+    List<String> deferred = params.getDeferredLogMessages();
+    if (deferred != null && !deferred.isEmpty()) {
+      params.getParams().put(AutoConfigurationHelper.DEFERRED_LOG_MESSAGES_KEY, deferred);
+    }
+
     // Create and return the connection implementation
     return new SnowflakeConnectionImpl(params.getUrl(), params.getParams());
   }

src/main/java/net/snowflake/client/internal/jdbc/DefaultSFConnectionHandler.java

@@ -38,6 +38,7 @@
 import net.snowflake.client.internal.core.SFSession;
 import net.snowflake.client.internal.core.SFSessionProperty;
 import net.snowflake.client.internal.core.SFStatement;
+import net.snowflake.client.internal.driver.AutoConfigurationHelper;
 import net.snowflake.client.internal.exception.SnowflakeSQLLoggedException;
 import net.snowflake.client.internal.jdbc.telemetryOOB.TelemetryService;
 import net.snowflake.client.internal.jdbc.util.DriverUtil;
@@ -143,6 +144,7 @@ protected void initialize(
       initSessionProperties(conStr, appID, appVersion);
       setClientConfig();
       initLogger();
+      replayDeferredLogMessages(properties);
       initHttpHeaderCustomizers(properties);
       logger.debug("Trying to establish session, JDBC driver: {}", DriverUtil.getJdbcJarname());
       if (!skipOpen) {
@@ -230,6 +232,26 @@ && systemGetProperty("java.util.logging.config.file") == null) {
     }
   }
 
+  @SuppressWarnings("unchecked")
+  private void replayDeferredLogMessages(Properties properties) {
+    if (properties == null) {
+      return;
+    }
+    Object deferredObj = properties.remove(AutoConfigurationHelper.DEFERRED_LOG_MESSAGES_KEY);
+    if (!(deferredObj instanceof List)) {
+      return;
+    }
+    // Only replay under JDK14Logger: under SLF4J/external JUL, the immediate log calls already
+    // reached the correct destination, so replaying would produce duplicates.
+    if (!(logger instanceof JDK14Logger)) {
+      return;
+    }
+    List<String> deferredMessages = (List<String>) deferredObj;
+    for (String msg : deferredMessages) {
+      logger.debug(msg);
+    }
+  }
+
   private Path getLogPath(String logPathFromConfig) throws SnowflakeSQLLoggedException {
     if (JDK14Logger.STDOUT.equalsIgnoreCase(logPathFromConfig)) {
       return null;

src/test/java/net/snowflake/client/internal/config/SFConnectionConfigParserTest.java

@@ -618,6 +618,69 @@ public void testNonStringPrivateKeyPreservedInThreeWayMerge() throws Exception {
     assertEquals("TOML_USER", data.getParams().get("user"));
   }
 
+  // Verifies deferred log messages are populated and provenance is sorted alphabetically
+  @Test
+  public void testDeferredLogMessagesAndSortedProvenance()
+      throws SnowflakeSQLException, IOException {
+    SnowflakeUtil.systemSetEnv(SNOWFLAKE_HOME_KEY, tempPath.toString());
+    SnowflakeUtil.systemSetEnv(SNOWFLAKE_DEFAULT_CONNECTION_NAME_KEY, "default");
+    prepareTomlWithDatabase("TOML_DB", "TOML_WH", "TOML_ROLE");
+
+    Properties info = new Properties();
+    info.setProperty("warehouse", "PROP_WH");
+    info.setProperty("schema", "PROP_SCHEMA");
+
+    ConnectionParameters data =
+        AutoConfigurationHelper.resolveConnectionParameters(
+            "jdbc:snowflake:auto?connectionName=default&db=URL_DB&tracing=WARNING", info);
+    assertNotNull(data);
+
+    List<String> deferred = data.getDeferredLogMessages();
+    assertNotNull(deferred);
+    assertFalse(deferred.isEmpty());
+
+    assertTrue(deferred.stream().anyMatch(m -> m.contains("Attempting to load the configuration")));
+    assertTrue(
+        deferred.stream().anyMatch(m -> m.contains("Reading connection parameters from file")));
+    assertTrue(deferred.stream().anyMatch(m -> m.contains("found in connections.toml")));
+    assertTrue(
+        deferred.stream()
+            .anyMatch(m -> m.contains("Url created using parameters from connection")));
+    assertTrue(deferred.stream().anyMatch(m -> m.contains("Autoconfiguration is enabled")));
+
+    String provenanceLine =
+        deferred.stream()
+            .filter(m -> m.contains("Auto-configuration resolved properties"))
+            .findFirst()
+            .orElse(null);
+    assertNotNull(provenanceLine);
+
+    // Provenance must be sorted alphabetically by key
+    int accountIdx = provenanceLine.indexOf("account(");
+    int dbIdx = provenanceLine.indexOf("db(");
+    int passwordIdx = provenanceLine.indexOf("password(");
+    int roleIdx = provenanceLine.indexOf("role(");
+    int schemaIdx = provenanceLine.indexOf("schema(");
+    int tracingIdx = provenanceLine.indexOf("tracing(");
+    int userIdx = provenanceLine.indexOf("user(");
+    int warehouseIdx = provenanceLine.indexOf("warehouse(");
+    assertTrue(accountIdx < dbIdx);
+    assertTrue(dbIdx < passwordIdx);
+    assertTrue(passwordIdx < roleIdx);
+    assertTrue(roleIdx < schemaIdx);
+    assertTrue(schemaIdx < tracingIdx);
+    assertTrue(tracingIdx < userIdx);
+    assertTrue(userIdx < warehouseIdx);
+
+    // Verify provenance content
+    assertTrue(provenanceLine.contains("db(URL(overrode TOML))"));
+    assertTrue(provenanceLine.contains("warehouse(PROP(overrode TOML))"));
+    assertTrue(provenanceLine.contains("schema(PROP)"));
+    assertTrue(provenanceLine.contains("tracing(URL)"));
+    assertTrue(provenanceLine.contains("role(TOML)"));
+    assertTrue(provenanceLine.contains("account(TOML)"));
+  }
+
   private void prepareTomlWithDatabase(String databaseValue) throws IOException {
     prepareTomlWithDatabase(databaseValue, null, null, null);
   }

src/test/java/net/snowflake/client/internal/jdbc/DefaultSFConnectionHandlerTest.java

@@ -3,6 +3,7 @@
 import static net.snowflake.client.api.http.HttpHeadersCustomizer.HTTP_HEADER_CUSTOMIZERS_PROPERTY_KEY;
 import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertNull;
 import static org.junit.jupiter.api.Assertions.assertTrue;
 import static org.mockito.ArgumentMatchers.anyList;
 import static org.mockito.Mockito.mock;
@@ -17,6 +18,7 @@
 import java.util.Properties;
 import net.snowflake.client.api.http.HttpHeadersCustomizer;
 import net.snowflake.client.internal.core.SFSession;
+import net.snowflake.client.internal.driver.AutoConfigurationHelper;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.mockito.ArgumentCaptor;
@@ -114,4 +116,22 @@ void testEmptyHttpHeaderCustomizersWhenPropertyHasOnlyInvalidTypes() throws SQLE
     verify(mockSession).setHttpHeadersCustomizers(listCaptor.capture());
     assertTrue(listCaptor.getValue().isEmpty());
   }
+
+  // Verifies deferred log messages are removed from Properties after replay
+  @Test
+  void testReplayDeferredLogMessagesRemovesKeyFromProperties() throws SQLException {
+    List<String> msgs = Arrays.asList("msg1", "msg2");
+    properties.put(AutoConfigurationHelper.DEFERRED_LOG_MESSAGES_KEY, msgs);
+
+    connectionHandler.initialize(connectString, "", "", properties);
+
+    assertNull(properties.get(AutoConfigurationHelper.DEFERRED_LOG_MESSAGES_KEY));
+  }
+
+  // Verifies no error when Properties has no deferred messages
+  @Test
+  void testReplayDeferredLogMessagesNoop() throws SQLException {
+    connectionHandler.initialize(connectString, "", "", properties);
+    assertNull(properties.get(AutoConfigurationHelper.DEFERRED_LOG_MESSAGES_KEY));
+  }
 }