SNOW-1650624: Opening Connection to Snowflake Can Take a Long Time (login-request)

[jtrumpower]

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

1. What version of .NET driver are you using?
   4.1

2. What operating system and processor architecture are you using?
   Linux 64ee2fc15573 4.14.322-246.539.amzn2.x86_64 Control+C to cancel a query support #1 SMP Wed Sep 6 22:22:06 UTC 2023 x86_64 Linux

3. What version of .NET framework are you using?
   .Net 8

4. What did you do?

Opening a connection to snowflake can take a long time. This is sometimes intermittent. I initiated an OpenAsync call and it took 10 seconds to open a connection to Snowflake. In the below screenshot, the connections in the pool have expired and it is opening two new connections to satisfy the min pool size. Followed by a query to get data. You can observe that opening the connection took 10 seconds but the query to get data only took 168ms.

5. What did you expect to see?

I expected the login to happen very quickly.

6. Can you set logging to DEBUG and collect the logs?
   extract-2024-09-04T16_34_31.797Z.csv

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

This is an issue during creation of a new session to be added to the pool. Specifically after the previous connections have expired. Working with a Snowflake support person they didn't see the request hit them until the end of the 10 second window. Therefore there seems to have been a 9 or so seconds window where it was just waiting to send the request. But there were no other requests hitting the server at the time and the CPU was idle. There seems to be some locking or some issue that happens when all the connections have expired and we are now opening a new connection, which the connector then says we need two to satisfy the minimum pool size, and each login-request takes 10 seconds. So do each session delete request. After the pool is populated, this doesn't seem to be an issue. Even opening new connections seems to be ok as long as the ones in the pool are not expired.

[sfc-gh-dszmolka]

hi and thank you for opening this issue with us.

To keep the efforts focused and avoid information duplication, please keep working with the Support Engineer dedicated to your case 00826200. I'm going to close this issue as the Support Engineer will guide you through the rest of the process (and in the meantime review the logs - appreciate you collecting it!)

[sfc-gh-dszmolka]

the logs indeed show an unexplainable wait time but i also not sure how this is achieved:

>>> "2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.Session.SessionPool - SessionPool::NewSessionAsync [pool
: account=account;user=uaser;expirationtimeout=2m;host=org-accoun t.snowflakecomputing.com;warehouse=wh;db=db;]"
"2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.SFSession - Closing session with id: 1159860221161490, u
ser: user, database: db, schema: , role: role, warehouse: wh, connection start timestamp: 1725466092912"
"2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] INFO Snowflake.Data.Core.SFSessionProperties - Start parsing connection string."
"2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.SFSession - Send closeSessionRequest"
"2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.SFSession - Closing session with id: 1159860221149206, u
ser: user, database: db, schema: , role: role, warehouse: wh, connection start timestamp: 1725466109091"
"2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.SFSession - Send closeSessionRequest"
>>> "2024-09-04T16:12:55.838Z","""""","""visualization-api""","2024-09-04 16:12:55,838 [.NET TP Worker] DEBUG Snowflake.Data.Core.Session.SessionPool - SessionPool::NewSession [pool: account=account;user=user;expirationtimeout=2m;host=org-accou t.snowflakecomputing.com;warehouse=wh;db=db;]"

my concern is, how do you open the connection both sync (SessionPool::NewSession) and async (SessionPool::NewSessionAsync) ?

I tried to reproduce by using OpenAsync and async queries with following naive approach, having 2m expiration timeout for connections + waiting for 3 minutes:

using System;
using System.Data;
using System.Data.Common;
using System.IO;

using Snowflake.Data.Core;
using Snowflake.Data.Client;

class App
{
    const string TOKENPATH = "/snowflake/session/token";

    static string getConnectionString(){
        string? account = Environment.GetEnvironmentVariable("SNOWFLAKE_ACCOUNT");
        string? database = Environment.GetEnvironmentVariable("SNOWFLAKE_DATABASE");
        string? schema = Environment.GetEnvironmentVariable("SNOWFLAKE_SCHEMA");
        string? host = Environment.GetEnvironmentVariable("SNOWFLAKE_HOST");
        if (File.Exists(TOKENPATH)) {
            // automatically set by env
            string token = File.ReadAllText(TOKENPATH);
            return $"account={account};authenticator=oauth;token={token};db={database};schema={schema};host={host}";
        } else {
            // basic auth, variables must be set by user
            string? user = Environment.GetEnvironmentVariable("SNOWFLAKE_USER");
            string? password = Environment.GetEnvironmentVariable("SNOWFLAKE_PASSWORD");
            return $"account={account};user={user};password={password};db={database};schema={schema};host={host}";
        }
    }

    static public async Task<int> doIt()
    {
        try
        {
	  string connectionString = getConnectionString() + ";POOLINGENABLED=true;EXPIRATIONTIMEOUT=2m;MINPOOLSIZE=2;MAXPOOLSIZE=10";
          using (SnowflakeDbConnection conn = new SnowflakeDbConnection(connectionString))
		{
      		  await conn.OpenAsync(CancellationToken.None).ConfigureAwait(false);
		  Console.WriteLine("connected to Snowflake");
      		  SnowflakeDbCommand cmd = (SnowflakeDbCommand)conn.CreateCommand();
      		  cmd.CommandText = "SELECT 10";
		  Console.WriteLine("issuing first query");
      		  var queryId = await cmd.ExecuteAsyncInAsyncMode(CancellationToken.None).ConfigureAwait(false);
		  DbDataReader reader = await cmd.GetResultsFromQueryIdAsync(queryId, CancellationToken.None).ConfigureAwait(false);
		  if (reader.Read())
		  {
		    Console.WriteLine("first query succeeded");
		  }

		  Console.WriteLine("now sleeping..");
		  Thread.Sleep(180000);

		  Console.WriteLine("issuing second query");
		  SnowflakeDbCommand cmd2 = (SnowflakeDbCommand)conn.CreateCommand();
                  cmd2.CommandText = "SELECT 20";
                  var queryId2 = await cmd2.ExecuteAsyncInAsyncMode(CancellationToken.None).ConfigureAwait(false);
                  DbDataReader reader2 = await cmd2.GetResultsFromQueryIdAsync(queryId, CancellationToken.None).ConfigureAwait(false);
                  if (reader.Read()) 
                  {       
                    Console.WriteLine("second query succeeded");
                  }  
		}
	  Console.WriteLine("finished queries");
	  return 0;
        }
        catch (Exception ex)
        {
            Console.WriteLine(ex.ToString());
        }
        Console.WriteLine("FAILED");
        return 1;
    }

    static async Task Main()
    {
      await doIt();
    }

}

but i didn't notice the 10s+ wait, actually after the sleep was concluded the reconnect + query was done within 2 seconds.
So probably i'm doing something different than you.

Would it be possible to provide a reproduction program on your Support case, which when run, leads to the issue you observing? That would greatly help the debugging effort. We thank you for your help in advance!