SNOW-1542394: Driver stuck in a state of enabling/disabling auto-commit when used with Spring Boot

[austinprete]

Please answer these questions before submitting your issue. In order to accurately debug the issue this information is required. Thanks!

1. What version of JDBC driver are you using?

Tried with both 3.16.1 and 3.17.0

2. What operating system and processor architecture are you using?

Behavior occurs both in MacOS Sonoma (when run locally) and in a Alpine Linux Docker container.

3. What version of Java are you using?

OpenJDK 18 with Kotlin 1.9.20 and Spring Boot 3.2.0

4. What did you do?

Used net.snowflake.client.jdbc.SnowflakeDriver as the primary data source in a Spring Boot app.

5. What did you expect to see?

Reading and writing to Snowflake (Hybrid) tables works as expected with Spring/JPA, but we are seeing a continual pattern of queries in the form:

alter session /* JDBC:SnowflakeConnectionV1.setAutoCommit*/ set autocommit=true
alter session /* JDBC:SnowflakeConnectionV1.setAutoCommit*/ set autocommit=false
commit
commit
[...] 

Spring defaults to autocommit=true and auto commit is enabled in our Snowflake account as well. So it is unclear why it is ever being set to false and then re-enabled. Note: this pattern of session updates happens even if not doing any other queries against the database, and occurs many times per second.

6. Can you set logging to DEBUG and collect the logs?

Will look into doing this in our Spring app.

7. What is your Snowflake account identifier, if any? (Optional)

[sfc-gh-wfateem]

Hi @austinprete,

Those alter session /* JDBC:SnowflakeConnectionV1.setAutoCommit*/ set autocommit= queries you're seeing are a direct result of the calling application invoking the Connection's setAutoCommit method. You can find more information about this method in the Java docs here. JDBC drivers will override this method, which is what we do here.

I ran a quick test using v3.17.0 to run two queries and this is all I'm seeing on the query history page, which is what I would expect:

The fact that you keep seeing those queries even when you're not actively querying your database tells me that there's likely a connection pool in use that calls the setAutoCommit method each time it creates a brand new connection. However, if you're seeing this happening several times per second, then it would imply that your connection pool is evicting connections too frequently. You can confirm if these calls are happening within the same session or not. If they're submitted as part of a new session then it would confirm that those are submitted after a new connection is created. You can add the session ID column in your query history page by clicking on the Columns button at the top right as shown here:

Then select Session ID:

Enabling debugging and setting the log level to TRACE would show us exactly when that setAutoCommit method is called, but it won't tell us who's invoking that method.

Do you have any information on how the JDBC connections are created in your application?

Do you have sample code that can be used to run a simple query to reproduce this issue you're seeing?

[austinprete]

Hi @sfc-gh-wfateem , thanks for the quick follow-up.

I will get back to you with the TRACE level logs in a bit, but I did have a chance to review Session IDs in the Query History and it looks like these statements are repeating even for the same session. Here's 15 seconds of query history for just one session:

[sfc-gh-wfateem]

Thanks for checking @austinprete.

It would then seem that the Java application calling the JDBC APIs is just calling the setAutoCommit(boolean) method repeatedly. The trace logs will show you the following log line every time that's invoked:

void setAutoCommit(boolean isAutoCommit)

Though, I'm not sure how helpful that is. You would need to step through the code to figure out who's calling the setAutoCommit method.

[sfc-gh-wfateem]

@austinprete were you able to make any progress with this issue?

[sfc-gh-wfateem]

@austinprete I was looking through the code to see if maybe there's something we can do to improve this. I found that once autoCommmit is called we change the internal state of the session here. However, we then go and issue a query to alter the session here, which is what you're seeing the query history page.

I believe the query might be redundant, but I'll need to discuss it with the team and look at it more carefully. I think the major downfall of removing that is that once you run into any problems related to transactions, we have no way of confirming if auto-commit was enabled or not without the debugging logs from the JDBC driver. It also might not be possible to do anything about it because of how transactions are handled at the backend: https://docs.snowflake.com/en/sql-reference/transactions

[austinprete]

Hi @sfc-gh-wfateem, thanks for following up. Sorry for the slow response here, been trying to find time to dig into this more but been pulled onto some other things in the meantime.

I was able to run with TRACE on and gather some logs in our deployed integration testing environment. I do see the behavior from the Query History represented in the logs, but not anything resembling a cause for it.

Example App Logs with TRACE level for Snowflake driver

However, the statement I made before that this happens both locally and in our deployed server (which is running in Amazon EKS) was somewhat wrong.

Locally the behavior is that these 3 statements repeat every minute (pretty much exactly on the minute) and only on a single session (even though multiple sessions are opened in the connection pool on app startup):

alter session /* JDBC:SnowflakeConnectionV1.setAutoCommit*/ set autocommit=false
commit
alter session /* JDBC:SnowflakeConnectionV1.setAutoCommit*/ set autocommit=true

Whereas in EKS it appears all the active sessions in the connection pool are continually making these calls, repeating every second or multiple times a second even for the same session ID.

Again, in the logs above, I don't see any reason why these are repeated so often, but I might also just not know what to look for.

One possibility I was wondering about to explain the difference between the behavior locally and in EKS (this is just a theory so feel free to correct me if it's not possible):

• If the latency between our Snowflake instance (which is running in US-East-1) and our app server (also in US-East-1) is low enough, could a check on the auto commit setting come before the setting is fully committed? Which would cause another setAutoCommit call to be made which sets it in the opposite direction, and so on?

Again, I don't know exactly how the driver is working and if any of this is multi-threaded, so the above might not really make sense in practice, but trying to think of things that could be different between the local and deployed environments.

[sfc-gh-wfateem]

Hey @austinprete,

I'm honestly not sure if we would be able to explain why that behavior is different between your local environment and EKS. At the end of the day, it's the calling application that decides when to invoke a connection's setAutoCommit(Boolean) method. We don't have any control over that.

The improvement I was thinking about is not going to be possible either. After reviewing the code and discussing it with a few contributors, it became clear that we have to issue an alter session statement to instruct Snowflake at the backend to flip the AUTOCOMMIT parameter.

We recently ran into a similar issue on another project with Hibernate involved. The way around it was to instruct Hibernate and to disable AUTOCOMMIT, in addition, we set AUTOCOMMIT to false in our JDBC driver.

There might be a way to do something similar in Spring.

[austinprete]

Hi @sfc-gh-wfateem , just following up here.

We made a recent change in our Spring configuration to no longer use JDBC for session management. Before that, we had 2 database configs, one for Postgres where sessions were stored, and one for Snowflake.

However, after dropping our use of the spring-session-jdbc Spring library altogether (using Redis now), we are now no longer seeing this constant auto-commit reset.

Not sure why that would have an impact, since the session configuration was set to use the Postges database (and we confirmed that's where sessions were being stored).

Regardless, we are now no longer seeing this issue, and it appears that there isn't anything that needs to be done in the driver itself at this point, so I'm going to mark this closed.

Thanks again for your help on this along the way!