From 5de53f9bf270babd5efcba81590211802ca9f3bf Mon Sep 17 00:00:00 2001 From: Krzysztof Nozderko Date: Tue, 7 May 2024 13:50:39 +0200 Subject: [PATCH] SNOW-986233 Log pool status (#936) ### Description SNOW-986233 Log pool status ### Checklist - [x] Code compiles correctly - [x] Code is formatted according to [Coding Conventions](../blob/master/CodingConventions.md) - [x] Created tests which fail without the change (if possible) - [x] All tests passing (`dotnet test`) - [x] Extended the README / documentation, if necessary - [x] Provide JIRA issue id (if possible) or GitHub issue id in PR name --- .github/workflows/main.yml | 6 +- .../ConnectionMultiplePoolsAsyncIT.cs | 5 +- .../UnitTests/Session/SessionPoolTest.cs | 80 ++++++++- .../Core/Session/ConnectionPoolManager.cs | 4 +- Snowflake.Data/Core/Session/IWaitingQueue.cs | 2 + .../Core/Session/NonWaitingQueue.cs | 5 + .../Core/Session/SFSessionProperty.cs | 52 ++++-- Snowflake.Data/Core/Session/SessionPool.cs | 167 +++++++++++------- .../Core/Session/SessionPoolState.cs | 29 +++ Snowflake.Data/Core/Session/WaitingQueue.cs | 9 +- Snowflake.Data/Snowflake.Data.csproj | 14 +- 11 files changed, 277 insertions(+), 96 deletions(-) create mode 100644 Snowflake.Data/Core/Session/SessionPoolState.cs diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index 03e4c591b..07c5e3a05 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -61,7 +61,7 @@ jobs: run: | cd Snowflake.Data.Tests dotnet restore - dotnet build -f ${{ matrix.dotnet }} + dotnet build -f ${{ matrix.dotnet }} '-p:DefineAdditionalConstants=SF_PUBLIC_ENVIRONMENT' - name: Run Tests run: | cd Snowflake.Data.Tests @@ -118,7 +118,7 @@ jobs: - name: Build Driver run: | dotnet restore - dotnet build + dotnet build '-p:DefineAdditionalConstants=SF_PUBLIC_ENVIRONMENT' - name: Run Tests run: | cd Snowflake.Data.Tests @@ -175,7 +175,7 @@ jobs: - name: Build Driver run: | dotnet restore - dotnet build + dotnet build '-p:DefineAdditionalConstants=SF_PUBLIC_ENVIRONMENT' - name: Run Tests run: | cd Snowflake.Data.Tests diff --git a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs index 8f7d3c0ab..9089cc996 100644 --- a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs +++ b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs @@ -1,4 +1,3 @@ -using System; using System.Data.Common; using System.Threading; using System.Threading.Tasks; @@ -7,6 +6,7 @@ using Snowflake.Data.Client; using Snowflake.Data.Core; using Snowflake.Data.Core.Session; +using Snowflake.Data.Log; using Snowflake.Data.Tests.Mock; using Snowflake.Data.Tests.Util; @@ -17,6 +17,7 @@ namespace Snowflake.Data.Tests.IntegrationTests public class ConnectionMultiplePoolsAsyncIT: SFBaseTestAsync { private readonly PoolConfig _previousPoolConfig = new PoolConfig(); + private readonly SFLogger logger = SFLoggerFactory.GetLogger(); [SetUp] public new void BeforeTest() @@ -65,6 +66,8 @@ public async Task TestDoNotAddToPoolInvalidConnectionAsync() // assert var pool = SnowflakeDbConnectionPool.GetPool(connection.ConnectionString); + var poolState = pool.GetCurrentState(); + logger.Warn($"Pool state: {poolState}"); Assert.Less(pool.GetCurrentPoolSize(), SFSessionHttpClientProperties.DefaultMinPoolSize); // for invalid connection string it is used default min pool size // cleanup diff --git a/Snowflake.Data.Tests/UnitTests/Session/SessionPoolTest.cs b/Snowflake.Data.Tests/UnitTests/Session/SessionPoolTest.cs index a4b54d6b9..a66146823 100644 --- a/Snowflake.Data.Tests/UnitTests/Session/SessionPoolTest.cs +++ b/Snowflake.Data.Tests/UnitTests/Session/SessionPoolTest.cs @@ -1,3 +1,5 @@ +using System.Net; +using System.Text.RegularExpressions; using NUnit.Framework; using Snowflake.Data.Core.Session; @@ -17,32 +19,32 @@ public void TestPoolParametersAreNotOverriden() // assert Assert.IsFalse(pool.IsConfigOverridden()); } - + [Test] public void TestOverrideMaxPoolSize() { // arrange var pool = SessionPool.CreateSessionPool(ConnectionString, null); var newMaxPoolSize = 15; - + // act pool.SetMaxPoolSize(newMaxPoolSize); - + // assert Assert.AreEqual(newMaxPoolSize, pool.GetMaxPoolSize()); Assert.IsTrue(pool.IsConfigOverridden()); } - + [Test] public void TestOverrideExpirationTimeout() { // arrange var pool = SessionPool.CreateSessionPool(ConnectionString, null); var newExpirationTimeoutSeconds = 15; - + // act pool.SetTimeout(newExpirationTimeoutSeconds); - + // assert Assert.AreEqual(newExpirationTimeoutSeconds, pool.GetTimeout()); Assert.IsTrue(pool.IsConfigOverridden()); @@ -56,10 +58,74 @@ public void TestOverrideSetPooling() // act pool.SetPooling(false); - + // assert Assert.IsFalse(pool.GetPooling()); Assert.IsTrue(pool.IsConfigOverridden()); } + + [Test] + [TestCase("account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443", "somePassword", " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;port=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;private_key=SomePrivateKey;port=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;token=someToken;port=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;private_key_pwd=somePrivateKeyPwd;port=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;proxyPassword=someProxyPassword;port=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("ACCOUNT=someAccount;DB=someDb;HOST=someHost;PASSWORD=somePassword;USER=SomeUser;PORT=443", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + [TestCase("ACCOUNT=\"someAccount\";DB=\"someDb\";HOST=\"someHost\";PASSWORD=\"somePassword\";USER=\"SomeUser\";PORT=\"443\"", null, " [pool: account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443;]")] + public void TestPoolIdentificationBasedOnConnectionString(string connectionString, string password, string expectedPoolIdentification) + { + // arrange + var securePassword = password == null ? null : new NetworkCredential("", password).SecurePassword; + var pool = SessionPool.CreateSessionPool(connectionString, securePassword); + + // act + var poolIdentification = pool.PoolIdentificationBasedOnConnectionString; + + // assert + Assert.AreEqual(expectedPoolIdentification, poolIdentification); + } + + [Test] + public void TestPoolIdentificationForInvalidConnectionString() + { + // arrange + var invalidConnectionString = "account=someAccount;db=someDb;host=someHost;user=SomeUser;port=443"; // invalid because password is not provided + var pool = SessionPool.CreateSessionPool(invalidConnectionString, null); + + // act + var poolIdentification = pool.PoolIdentificationBasedOnConnectionString; + + // assert + Assert.AreEqual(" [pool: could not parse connection string]", poolIdentification); + } + + [Test] + public void TestPoolIdentificationBasedOnInternalId() + { + // arrange + var connectionString = "account=someAccount;db=someDb;host=someHost;password=somePassword;user=SomeUser;port=443"; + var pool = SessionPool.CreateSessionPool(connectionString, null); + var poolIdRegex = new Regex(@"^ \[pool: [0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}\]$"); + + // act + var poolIdentification = pool.PoolIdentificationBasedOnInternalId; + + // assert + Assert.IsTrue(poolIdRegex.IsMatch(poolIdentification)); + } + + [Test] + public void TestPoolIdentificationForOldPool() + { + // arrange + var pool = SessionPool.CreateSessionCache(); + + // act + var poolIdentification = pool.PoolIdentification(); + + // assert + Assert.AreEqual("", poolIdentification); + } } } diff --git a/Snowflake.Data/Core/Session/ConnectionPoolManager.cs b/Snowflake.Data/Core/Session/ConnectionPoolManager.cs index 388714876..4f70ab691 100644 --- a/Snowflake.Data/Core/Session/ConnectionPoolManager.cs +++ b/Snowflake.Data/Core/Session/ConnectionPoolManager.cs @@ -42,13 +42,13 @@ public Task GetSessionAsync(string connectionString, SecureString pas public bool AddSession(SFSession session) { - s_logger.Debug($"ConnectionPoolManager::AddSession for {session.ConnectionString}"); + s_logger.Debug("ConnectionPoolManager::AddSession"); return GetPool(session.ConnectionString, session.Password).AddSession(session, true); } public void ReleaseBusySession(SFSession session) { - s_logger.Debug($"ConnectionPoolManager::ReleaseBusySession for {session.ConnectionString}"); + s_logger.Debug("ConnectionPoolManager::ReleaseBusySession"); GetPool(session.ConnectionString, session.Password).ReleaseBusySession(session); } diff --git a/Snowflake.Data/Core/Session/IWaitingQueue.cs b/Snowflake.Data/Core/Session/IWaitingQueue.cs index 6759e9a0d..5cc895026 100644 --- a/Snowflake.Data/Core/Session/IWaitingQueue.cs +++ b/Snowflake.Data/Core/Session/IWaitingQueue.cs @@ -10,6 +10,8 @@ internal interface IWaitingQueue bool IsAnyoneWaiting(); + int WaitingCount(); + bool IsWaitingEnabled(); } } diff --git a/Snowflake.Data/Core/Session/NonWaitingQueue.cs b/Snowflake.Data/Core/Session/NonWaitingQueue.cs index 5604ea4a8..1e7f9ee64 100644 --- a/Snowflake.Data/Core/Session/NonWaitingQueue.cs +++ b/Snowflake.Data/Core/Session/NonWaitingQueue.cs @@ -18,6 +18,11 @@ public bool IsAnyoneWaiting() return false; } + public int WaitingCount() + { + return 0; + } + public bool IsWaitingEnabled() { return false; diff --git a/Snowflake.Data/Core/Session/SFSessionProperty.cs b/Snowflake.Data/Core/Session/SFSessionProperty.cs index 4121bae83..3896f809a 100644 --- a/Snowflake.Data/Core/Session/SFSessionProperty.cs +++ b/Snowflake.Data/Core/Session/SFSessionProperty.cs @@ -11,6 +11,7 @@ using Snowflake.Data.Core.Authenticator; using System.Data.Common; using System.Linq; +using System.Text; using System.Text.RegularExpressions; namespace Snowflake.Data.Core @@ -23,7 +24,7 @@ internal enum SFSessionProperty DB, [SFSessionPropertyAttr(required = false)] HOST, - [SFSessionPropertyAttr(required = true)] + [SFSessionPropertyAttr(required = true, IsSecret = true)] PASSWORD, [SFSessionPropertyAttr(required = false, defaultValue = "443")] PORT, @@ -45,11 +46,11 @@ internal enum SFSessionProperty VALIDATE_DEFAULT_PARAMETERS, [SFSessionPropertyAttr(required = false)] PRIVATE_KEY_FILE, - [SFSessionPropertyAttr(required = false)] + [SFSessionPropertyAttr(required = false, IsSecret = true)] PRIVATE_KEY_PWD, - [SFSessionPropertyAttr(required = false)] + [SFSessionPropertyAttr(required = false, IsSecret = true)] PRIVATE_KEY, - [SFSessionPropertyAttr(required = false)] + [SFSessionPropertyAttr(required = false, IsSecret = true)] TOKEN, [SFSessionPropertyAttr(required = false, defaultValue = "false")] INSECUREMODE, @@ -61,7 +62,7 @@ internal enum SFSessionProperty PROXYPORT, [SFSessionPropertyAttr(required = false)] PROXYUSER, - [SFSessionPropertyAttr(required = false)] + [SFSessionPropertyAttr(required = false, IsSecret = true)] PROXYPASSWORD, [SFSessionPropertyAttr(required = false)] NONPROXYHOSTS, @@ -116,21 +117,22 @@ class SFSessionPropertyAttr : Attribute public bool required { get; set; } public string defaultValue { get; set; } + + public bool IsSecret { get; set; } = false; } class SFSessionProperties : Dictionary { private static SFLogger logger = SFLoggerFactory.GetLogger(); + internal string ConnectionStringWithoutSecrets { get; set; } + // Connection string properties to obfuscate in the log - private static List secretProps = - new List{ - SFSessionProperty.PASSWORD, - SFSessionProperty.PRIVATE_KEY, - SFSessionProperty.TOKEN, - SFSessionProperty.PRIVATE_KEY_PWD, - SFSessionProperty.PROXYPASSWORD, - }; + private static readonly List s_secretProps = Enum.GetValues(typeof(SFSessionProperty)) + .Cast() + .Where(p => p.GetAttribute().IsSecret) + .Select(p => p.ToString()) + .ToList(); private static readonly List s_accountRegexStrings = new List { @@ -196,6 +198,8 @@ internal static SFSessionProperties ParseConnectionString(string connectionStrin builder.Keys.CopyTo(keys, 0); builder.Values.CopyTo(values,0); + properties.ConnectionStringWithoutSecrets = BuildConnectionStringWithoutSecrets(ref keys, ref values); + for(var i=0; i _idleSessions; private readonly IWaitingQueue _waitingForIdleSessionQueue; private readonly ISessionCreationTokenCounter _sessionCreationTokenCounter; private readonly ISessionCreationTokenCounter _noPoolingSessionCreationTokenCounter = new NonCountingSessionCreationTokenCounter(); internal string ConnectionString { get; } internal SecureString Password { get; } + private readonly string _connectionStringWithoutSecrets; private readonly ICounter _busySessionsCounter; private ISessionPoolEventHandler _sessionPoolEventHandler = new SessionPoolEventHandler(); // a way to inject some additional behaviour after certain events. Can be used for example to measure time of given steps. private readonly ConnectionPoolConfig _poolConfig; @@ -41,13 +43,14 @@ private SessionPool() _poolConfig = new ConnectionPoolConfig(); } - private SessionPool(string connectionString, SecureString password, ConnectionPoolConfig poolConfig) + private SessionPool(string connectionString, SecureString password, ConnectionPoolConfig poolConfig, string connectionStringWithoutSecrets) { // acquiring a lock not needed because one is already acquired in ConnectionPoolManager _idleSessions = new List(); _busySessionsCounter = new NonNegativeCounter(); ConnectionString = connectionString; Password = password; + _connectionStringWithoutSecrets = connectionStringWithoutSecrets; _waitingForIdleSessionQueue = new WaitingQueue(); _poolConfig = poolConfig; _sessionCreationTokenCounter = new SessionCreationTokenCounter(_poolConfig.ConnectionTimeout); @@ -57,9 +60,10 @@ private SessionPool(string connectionString, SecureString password, ConnectionPo internal static SessionPool CreateSessionPool(string connectionString, SecureString password) { - s_logger.Debug($"Creating a pool identified by connection string: {connectionString}"); - var poolConfig = ExtractConfig(connectionString, password); - return new SessionPool(connectionString, password, poolConfig); + s_logger.Debug("Creating a connection pool"); + var extracted = ExtractConfig(connectionString, password); + s_logger.Debug("Creating a connection pool identified by: " + extracted.Item2); + return new SessionPool(connectionString, password, extracted.Item1, extracted.Item2); } ~SessionPool() @@ -81,7 +85,7 @@ internal static ISessionFactory SessionFactory private void CleanExpiredSessions() { - s_logger.Debug("SessionPool::CleanExpiredSessions"); + s_logger.Debug("SessionPool::CleanExpiredSessions" + PoolIdentification()); lock (_sessionPoolLock) { var timeNow = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); @@ -97,24 +101,24 @@ private void CleanExpiredSessions() } } - private static ConnectionPoolConfig ExtractConfig(string connectionString, SecureString password) + private static Tuple ExtractConfig(string connectionString, SecureString password) { try { var properties = SFSessionProperties.ParseConnectionString(connectionString, password); var extractedProperties = SFSessionHttpClientProperties.ExtractAndValidate(properties); - return extractedProperties.BuildConnectionPoolConfig(); + return Tuple.Create(extractedProperties.BuildConnectionPoolConfig(), properties.ConnectionStringWithoutSecrets); } catch (SnowflakeDbException exception) { s_logger.Error("Could not extract pool configuration, using default one", exception); - return new ConnectionPoolConfig(); + return Tuple.Create(new ConnectionPoolConfig(), "could not parse connection string"); } } internal SFSession GetSession(string connStr, SecureString password) { - s_logger.Debug("SessionPool::GetSession"); + s_logger.Debug("SessionPool::GetSession" + PoolIdentification()); if (!GetPooling()) return NewNonPoolingSession(connStr, password); var sessionOrCreateTokens = GetIdleSession(connStr); @@ -129,7 +133,7 @@ internal SFSession GetSession(string connStr, SecureString password) internal async Task GetSessionAsync(string connStr, SecureString password, CancellationToken cancellationToken) { - s_logger.Debug("SessionPool::GetSessionAsync"); + s_logger.Debug("SessionPool::GetSessionAsync" + PoolIdentification()); if (!GetPooling()) return await NewNonPoolingSessionAsync(connStr, password, cancellationToken).ConfigureAwait(false); var sessionOrCreateTokens = GetIdleSession(connStr); @@ -178,22 +182,22 @@ internal void SetSessionPoolEventHandler(ISessionPoolEventHandler sessionPoolEve private SessionOrCreationTokens GetIdleSession(string connStr) { - s_logger.Debug("SessionPool::GetIdleSession"); + s_logger.Debug("SessionPool::GetIdleSession" + PoolIdentification()); lock (_sessionPoolLock) { if (_waitingForIdleSessionQueue.IsAnyoneWaiting()) { - s_logger.Debug("SessionPool::GetIdleSession - someone is already waiting for a session, request is going to be queued"); + s_logger.Debug("SessionPool::GetIdleSession - someone is already waiting for a session, request is going to be queued" + PoolIdentification()); } else { var session = ExtractIdleSession(connStr); if (session != null) { - s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, an idle session was retrieved from the pool"); + s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, an idle session was retrieved from the pool" + PoolIdentification()); return new SessionOrCreationTokens(session); } - s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, but could not find any idle session available in the pool"); + s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, but could not find any idle session available in the pool" + PoolIdentification()); var sessionsCount = AllowedNumberOfNewSessionCreations(1); if (sessionsCount > 0) { @@ -232,10 +236,10 @@ private int AllowedNumberOfNewSessionCreations(int atLeastCount) var maxSessionsToCreate = _poolConfig.MaxPoolSize - currentSize; var sessionsNeeded = Math.Max(_poolConfig.MinPoolSize - currentSize, atLeastCount); var sessionsToCreate = Math.Min(sessionsNeeded, maxSessionsToCreate); - s_logger.Debug($"SessionPool - allowed to create {sessionsToCreate} sessions, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}"); + s_logger.Debug($"SessionPool - allowed to create {sessionsToCreate} sessions, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}" + PoolIdentification()); return sessionsToCreate; } - s_logger.Debug($"SessionPool - not allowed to create a session, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}"); + s_logger.Debug($"SessionPool - not allowed to create a session, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}" + PoolIdentification()); return 0; } @@ -245,7 +249,7 @@ private SFSession WaitForSession(string connStr) { if (TimeoutHelper.IsInfinite(_poolConfig.WaitingForIdleSessionTimeout)) throw new Exception("WaitingForIdleSessionTimeout cannot be infinite"); - s_logger.Info($"SessionPool::WaitForSession for {(long) _poolConfig.WaitingForIdleSessionTimeout.TotalMilliseconds} ms timeout"); + s_logger.Info($"SessionPool::WaitForSession for {(long) _poolConfig.WaitingForIdleSessionTimeout.TotalMilliseconds} ms timeout" + PoolIdentification()); _sessionPoolEventHandler.OnWaitingForSessionStarted(this); var beforeWaitingTimeMillis = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); long nowTimeMillis = beforeWaitingTimeMillis; @@ -256,25 +260,25 @@ private SFSession WaitForSession(string connStr) var successful = _waitingForIdleSessionQueue.Wait((int) timeoutLeftMillis, CancellationToken.None); if (successful) { - s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted"); + s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted" + PoolIdentification()); _sessionPoolEventHandler.OnWaitingForSessionSuccessful(this); lock (_sessionPoolLock) { var session = ExtractIdleSession(connStr); if (session != null) { - s_logger.Debug($"SessionPool::WaitForSession - provided an idle session"); + s_logger.Debug("SessionPool::WaitForSession - provided an idle session" + PoolIdentification()); return session; } } } else { - s_logger.Debug($"SessionPool::WaitForSession - woken without a session granted"); + s_logger.Debug("SessionPool::WaitForSession - woken without a session granted" + PoolIdentification()); } nowTimeMillis = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); } - s_logger.Info($"SessionPool::WaitForSession - could not find any idle session available withing a given timeout"); + s_logger.Info("SessionPool::WaitForSession - could not find any idle session available withing a given timeout" + PoolIdentification()); throw WaitingFailedException(); } @@ -291,12 +295,12 @@ private SFSession ExtractIdleSession(string connStr) var timeNow = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); if (session.IsExpired(_poolConfig.ExpirationTimeout, timeNow)) { - Task.Run(() => session.close()); // TODO: cherry-pick SNOW-984600 + Task.Run(() => session.close()); i--; } else { - s_logger.Debug($"reuse pooled session with sid {session.sessionId}"); + s_logger.Debug($"reuse pooled session with sid {session.sessionId}" + PoolIdentification()); _busySessionsCounter.Increase(); return session; } @@ -310,18 +314,19 @@ private SFSession NewNonPoolingSession(String connectionString, SecureString pas private SFSession NewSession(String connectionString, SecureString password, SessionCreationToken sessionCreationToken) { - s_logger.Debug("SessionPool::NewSession"); + s_logger.Debug("SessionPool::NewSession" + PoolIdentification()); try { var session = s_sessionFactory.NewSession(connectionString, password); session.Open(); - s_logger.Debug("SessionPool::NewSession - opened"); + s_logger.Debug("SessionPool::NewSession - opened" + PoolIdentification()); if (GetPooling()) { lock (_sessionPoolLock) { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); _busySessionsCounter.Increase(); + s_logger.Debug($"Pool state after creating a session {GetCurrentState()}" + PoolIdentification()); } } _sessionPoolEventHandler.OnNewSessionCreated(this); @@ -332,6 +337,13 @@ private SFSession NewSession(String connectionString, SecureString password, Ses { // Otherwise when Dispose() is called, the close request would timeout. _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); + if (GetPooling()) + { + lock (_sessionPoolLock) + { + s_logger.Debug($"Failed to create a new session {GetCurrentState()}" + PoolIdentification()); + } + } if (e is SnowflakeDbException) throw; throw new SnowflakeDbException( @@ -350,7 +362,7 @@ private Task NewNonPoolingSessionAsync( private Task NewSessionAsync(String connectionString, SecureString password, SessionCreationToken sessionCreationToken, CancellationToken cancellationToken) { - s_logger.Debug("SessionPool::NewSessionAsync"); + s_logger.Debug("SessionPool::NewSessionAsync" + PoolIdentification()); var session = s_sessionFactory.NewSession(connectionString, password); return session .OpenAsync(cancellationToken) @@ -359,6 +371,13 @@ private Task NewSessionAsync(String connectionString, SecureString pa if (previousTask.IsFaulted || previousTask.IsCanceled) { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); + if (GetPooling()) + { + lock (_sessionPoolLock) + { + s_logger.Debug($"Failed to create a new session {GetCurrentState()}" + PoolIdentification()); + } + } } if (previousTask.IsFaulted && previousTask.Exception != null) @@ -378,6 +397,7 @@ private Task NewSessionAsync(String connectionString, SecureString pa { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); _busySessionsCounter.Increase(); + s_logger.Debug($"Pool state after creating a session {GetCurrentState()}" + PoolIdentification()); } } @@ -390,18 +410,14 @@ private Task NewSessionAsync(String connectionString, SecureString pa internal void ReleaseBusySession(SFSession session) { - s_logger.Debug("SessionPool::ReleaseBusySession"); - int currentPoolSize; + s_logger.Debug("SessionPool::ReleaseBusySession" + PoolIdentification()); + SessionPoolState poolState; lock (_sessionPoolLock) { _busySessionsCounter.Decrease(); - currentPoolSize = GetCurrentPoolSize(); + poolState = GetCurrentState(); } - var currentSizeMessageOldPool = $"After releasing a busy session from the pool, the pool size is: {currentPoolSize}"; - var poolSizeMessage = IsMultiplePoolsVersion() - ? $"{currentSizeMessageOldPool} - pool identified by: {ConnectionString}" - : currentSizeMessageOldPool; - s_logger.Debug(poolSizeMessage); + s_logger.Debug($"After releasing a busy session from the pool {poolState}" + PoolIdentification()); } internal bool AddSession(SFSession session, bool ensureMinPoolSize) @@ -413,11 +429,7 @@ internal bool AddSession(SFSession session, bool ensureMinPoolSize) ReleaseBusySession(session); return false; } - const string AddSessionMessage = "SessionPool::AddSession"; - var addSessionMessage = IsMultiplePoolsVersion() - ? $"{AddSessionMessage} - returning session to pool identified by connection string: {ConnectionString}" - : AddSessionMessage; - s_logger.Debug(addSessionMessage); + s_logger.Debug("SessionPool::AddSession" + PoolIdentification()); var result = ReturnSessionToPool(session, ensureMinPoolSize); var wasSessionReturnedToPool = result.Item1; var sessionCreationTokens = result.Item2; @@ -433,9 +445,12 @@ private Tuple> ReturnSessionToPool(SFSession se lock (_sessionPoolLock) { _busySessionsCounter.Decrease(); - return ensureMinPoolSize - ? Tuple.Create(false, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokens = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolState = GetCurrentState(); + s_logger.Debug($"Could not return session to pool {poolState}" + PoolIdentification()); + return Tuple.Create(false, sessionCreationTokens); } } @@ -445,34 +460,33 @@ private Tuple> ReturnSessionToPool(SFSession se CleanExpiredSessions(); if (session.IsExpired(_poolConfig.ExpirationTimeout, DateTimeOffset.UtcNow.ToUnixTimeMilliseconds())) // checking again because we could have spent some time waiting for a lock { - return ensureMinPoolSize - ? Tuple.Create(false, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokens = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolState = GetCurrentState(); + s_logger.Debug($"Could not return session to pool {poolState}" + PoolIdentification()); + return Tuple.Create(false, sessionCreationTokens); } - if (GetCurrentPoolSize() >= _poolConfig.MaxPoolSize) + var poolStateBeforeReturningToPool = GetCurrentState(); + if (poolStateBeforeReturningToPool.Count() >= _poolConfig.MaxPoolSize) { - s_logger.Warn($"Pool is full - unable to add session with sid {session.sessionId}"); + s_logger.Warn($"Pool is full - unable to add session with sid {session.sessionId} {poolStateBeforeReturningToPool}"); return Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); } - s_logger.Debug($"pool connection with sid {session.sessionId}"); _idleSessions.Add(session); _waitingForIdleSessionQueue.OnResourceIncrease(); - return ensureMinPoolSize - ? Tuple.Create(true, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(true, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokensAfterReturningToPool = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolStateAfterReturningToPool = GetCurrentState(); + s_logger.Debug($"returned session with sid {session.sessionId} to pool {poolStateAfterReturningToPool}" + PoolIdentification()); + return Tuple.Create(true, sessionCreationTokensAfterReturningToPool); } } internal void ClearSessions() { - if (IsMultiplePoolsVersion()) - { - s_logger.Debug($"SessionPool::ClearSessions for connection string: {ConnectionString}"); - } - else - { - s_logger.Debug("SessionPool::ClearSessions"); - } + s_logger.Debug("SessionPool::ClearSessions" + PoolIdentification()); lock (_sessionPoolLock) { _busySessionsCounter.Reset(); @@ -482,7 +496,7 @@ internal void ClearSessions() internal void ClearIdleSessions() { - s_logger.Debug("SessionPool::ClearIdleSessions"); + s_logger.Debug("SessionPool::ClearIdleSessions" + PoolIdentification()); lock (_sessionPoolLock) { foreach (SFSession session in _idleSessions) @@ -495,7 +509,7 @@ internal void ClearIdleSessions() internal async void ClearAllPoolsAsync() { - s_logger.Debug("SessionPool::ClearAllPoolsAsync"); + s_logger.Debug("SessionPool::ClearAllPoolsAsync" + PoolIdentification()); IEnumerable idleSessionsCopy; lock (_sessionPoolLock) { @@ -510,6 +524,7 @@ internal async void ClearAllPoolsAsync() public void SetMaxPoolSize(int size) { + s_logger.Debug($"SessionPool::SetMaxPoolSize({size})" + PoolIdentification()); _poolConfig.MaxPoolSize = size; _configOverriden = true; } @@ -521,6 +536,7 @@ public int GetMaxPoolSize() public void SetTimeout(long seconds) { + s_logger.Debug($"SessionPool::SetTimeout({seconds})" + PoolIdentification()); var timeout = seconds < 0 ? TimeoutHelper.Infinity() : TimeSpan.FromSeconds(seconds); _poolConfig.ExpirationTimeout = timeout; _configOverriden = true; @@ -536,9 +552,20 @@ public int GetCurrentPoolSize() return _idleSessions.Count + _busySessionsCounter.Count() + _sessionCreationTokenCounter.Count(); } + public SessionPoolState GetCurrentState() + { + return new SessionPoolState( + _idleSessions.Count, + _busySessionsCounter.Count(), + _sessionCreationTokenCounter.Count(), + _waitingForIdleSessionQueue.WaitingCount(), + IsMultiplePoolsVersion() + ); + } + public bool SetPooling(bool isEnable) { - s_logger.Info($"SessionPool::SetPooling({isEnable})"); + s_logger.Info($"SessionPool::SetPooling({isEnable})" + PoolIdentification()); if (_poolConfig.PoolingEnabled == isEnable) return false; _poolConfig.PoolingEnabled = isEnable; @@ -567,5 +594,21 @@ internal List GetIdleSessionsStartTimes() return _idleSessions.Select(s => s.GetStartTime()).ToList(); } } + + internal string PoolIdentification() + { + if (!IsMultiplePoolsVersion()) + return ""; + return +#if SF_PUBLIC_ENVIRONMENT + PoolIdentificationBasedOnInternalId; +#else + PoolIdentificationBasedOnConnectionString; +#endif + } + + internal string PoolIdentificationBasedOnConnectionString => " [pool: " + _connectionStringWithoutSecrets + "]"; + + internal string PoolIdentificationBasedOnInternalId => " [pool: " + _id + "]"; } } diff --git a/Snowflake.Data/Core/Session/SessionPoolState.cs b/Snowflake.Data/Core/Session/SessionPoolState.cs new file mode 100644 index 000000000..4f29858c3 --- /dev/null +++ b/Snowflake.Data/Core/Session/SessionPoolState.cs @@ -0,0 +1,29 @@ +namespace Snowflake.Data.Core.Session +{ + public class SessionPoolState + { + private readonly int _idleSessionsCount; + private readonly int _busySessionsCount; + private readonly int _sessionCreationsCount; + private readonly int _waitingCount; + private readonly bool _extensiveFormat; + + public SessionPoolState(int idleSessionsCount, int busySessionsCount, int sessionCreationsCount, int waitingCount, bool extensiveFormat) + { + _idleSessionsCount = idleSessionsCount; + _busySessionsCount = busySessionsCount; + _sessionCreationsCount = sessionCreationsCount; + _waitingCount = waitingCount; + _extensiveFormat = extensiveFormat; + } + + public int Count() => _idleSessionsCount + _busySessionsCount + _sessionCreationsCount; + + public override string ToString() + { + return _extensiveFormat + ? $"[pool size: {Count()} (idle sessions: {_idleSessionsCount}, busy sessions: {_busySessionsCount}, sessions under creation: {_sessionCreationsCount}), waiting sessions: {_waitingCount}]" + : $"[pool size: {Count()}]"; + } + } +} diff --git a/Snowflake.Data/Core/Session/WaitingQueue.cs b/Snowflake.Data/Core/Session/WaitingQueue.cs index c8cd23390..bdd64b9f5 100644 --- a/Snowflake.Data/Core/Session/WaitingQueue.cs +++ b/Snowflake.Data/Core/Session/WaitingQueue.cs @@ -8,7 +8,7 @@ internal class WaitingQueue: IWaitingQueue { private readonly ReaderWriterLockSlim _lock = new ReaderWriterLockSlim(); private readonly List _queue = new List(); - + public bool Wait(int millisecondsTimeout, CancellationToken cancellationToken) { var semaphore = new SemaphoreSlim(0, 1); @@ -67,11 +67,14 @@ public void OnResourceIncrease() semaphore?.Release(); } - public bool IsAnyoneWaiting() { + public bool IsAnyoneWaiting() => WaitingCount() > 0; + + public int WaitingCount() + { _lock.EnterReadLock(); try { - return _queue.Count > 0; + return _queue.Count; } finally { diff --git a/Snowflake.Data/Snowflake.Data.csproj b/Snowflake.Data/Snowflake.Data.csproj index 0621c5fb0..cdfbabed2 100644 --- a/Snowflake.Data/Snowflake.Data.csproj +++ b/Snowflake.Data/Snowflake.Data.csproj @@ -17,7 +17,7 @@ Full 7.3 - + @@ -31,7 +31,7 @@ - + @@ -45,7 +45,7 @@ - + full True @@ -55,13 +55,17 @@ full True - + true true $(Version) - + + + $(DefineConstants);$(DefineAdditionalConstants) + +