dev: more logging ado.net (#172)

ydb-platform · Aug 16, 2024 · b76d18e · b76d18e
1 parent 8c2d1df
commit b76d18e
Show file tree

Hide file tree

Showing 6 changed files with 29 additions and 21 deletions.
diff --git a/.github/workflows/slo.yml b/.github/workflows/slo.yml
@@ -33,6 +33,7 @@ jobs:
         if: env.DOCKER_REPO != null
         env:
           DOCKER_REPO: ${{ secrets.SLO_DOCKER_REPO }}
+        continue-on-error: true
         with:
           GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }}
           KUBECONFIG_B64: ${{ secrets.SLO_KUBE_CONFIG }}

diff --git a/slo/src/Internal/SloContext.cs b/slo/src/Internal/SloContext.cs
@@ -11,7 +11,7 @@ public abstract class SloContext<T> where T : IDisposable
 {
     // ReSharper disable once StaticMemberInGenericType
     protected static readonly ILoggerFactory Factory =
-        LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Information));
+        LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Debug));
 
     protected static readonly ILogger Logger = Factory.CreateLogger<SloContext<T>>();
 

diff --git a/src/Ydb.Sdk/src/Driver.cs b/src/Ydb.Sdk/src/Driver.cs
@@ -233,9 +233,8 @@ private async Task<Status> DiscoverEndpoints()
 
         var resultProto = response.Operation.Result.Unpack<ListEndpointsResult>();
 
-        _logger.LogInformation($"Successfully discovered endpoints: {resultProto.Endpoints.Count}" +
-                               $", self location: {resultProto.SelfLocation}" +
-                               $", sdk info: {_sdkInfo}");
+        _logger.LogInformation("Successfully discovered endpoints: {}, self location: {}, sdk info: {}",
+            resultProto.Endpoints.Count, resultProto.SelfLocation, _sdkInfo);
 
         _endpointPool.Reset(resultProto.Endpoints
             .Select(endpointSettings => new EndpointSettings(

diff --git a/src/Ydb.Sdk/src/Pool/SessionPool.cs b/src/Ydb.Sdk/src/Pool/SessionPool.cs
@@ -7,17 +7,18 @@ namespace Ydb.Sdk.Pool;
 
 internal abstract class SessionPool<TSession> where TSession : SessionBase<TSession>
 {
-    private readonly ILogger<SessionPool<TSession>> _logger;
     private readonly SemaphoreSlim _semaphore;
     private readonly ConcurrentQueue<TSession> _idleSessions = new();
     private readonly int _size;
 
+    protected readonly ILogger<SessionPool<TSession>> Logger;
+
     private volatile int _waitingCount;
     private volatile bool _disposed;
 
     protected SessionPool(ILogger<SessionPool<TSession>> logger, int? maxSessionPool = null)
     {
-        _logger = logger;
+        Logger = logger;
         _size = maxSessionPool ?? 100;
         _semaphore = new SemaphoreSlim(_size);
     }
@@ -41,23 +42,20 @@ internal async Task<TSession> GetSession()
 
         if (session != null) // not active
         {
+            Logger.LogDebug("Session[{Id}] isn't active, creating new session", session.SessionId);
+
             _ = DeleteNotActiveSession(session);
         }
 
         try
         {
             return await CreateSession();
         }
-        catch (Driver.TransportException) // Transport exception
-        {
-            Release();
-
-            throw;
-        }
-        catch (StatusUnsuccessfulException)
+        catch (Exception e)
         {
             Release();
 
+            Logger.LogError(e, "Failed to create a session");
             throw;
         }
     }
@@ -104,7 +102,7 @@ internal async Task<T> ExecOnSession<T>(Func<TSession, Task<T>> onSession, Retry
                         throw;
                     }
 
-                    _logger.LogTrace(
+                    Logger.LogTrace(
                         "Retry: attempt {attempt}, Session ${session?.SessionId}, idempotent error {status} retrying",
                         attempt, session?.SessionId, statusErr);
                     await Task.Delay(retryRule.BackoffSettings.CalcBackoff(attempt));
@@ -162,7 +160,7 @@ private Task DeleteNotActiveSession(TSession session)
     {
         return DeleteSession(session).ContinueWith(s =>
         {
-            _logger.LogDebug("Session[{id}] removed with status {status}", session.SessionId, s.Result);
+            Logger.LogDebug("Session[{id}] removed with status {status}", session.SessionId, s.Result);
         });
     }
 

diff --git a/src/Ydb.Sdk/src/Services/Query/SessionPool.cs b/src/Ydb.Sdk/src/Services/Query/SessionPool.cs
@@ -48,7 +48,7 @@ protected override async Task<Session> CreateSession()
             try
             {
                 await using var stream = _driver.StreamCall(QueryService.AttachSessionMethod, new AttachSessionRequest
-                    { SessionId = response.SessionId }, AttachSessionSettings);
+                    { SessionId = session.SessionId }, AttachSessionSettings);
 
                 if (!await stream.MoveNextAsync())
                 {
@@ -64,10 +64,18 @@ protected override async Task<Session> CreateSession()
                 {
                     await foreach (var sessionState in stream) // watch attach stream session cycle life
                     {
-                        session.OnStatus(Status.FromProto(sessionState.Status, sessionState.Issues));
+                        var sessionStateStatus = Status.FromProto(sessionState.Status, sessionState.Issues);
 
+                        Logger.LogDebug("Session[{SessionId}] was received the status from the attach stream: {Status}",
+                            session.SessionId, sessionStateStatus);
+
+                        session.OnStatus(sessionStateStatus);
+
+                        // ReSharper disable once InvertIf
                         if (!session.IsActive)
                         {
+                            Logger.LogWarning("Session[{SessionId}] is deactivated", session.SessionId);
+
                             return;
                         }
                     }
@@ -85,6 +93,8 @@ protected override async Task<Session> CreateSession()
             finally
             {
                 session.IsActive = false;
+
+                Logger.LogTrace("Attached stream is closed");
             }
         });
 

diff --git a/src/Ydb.Sdk/tests/Auth/StaticAuthTests.cs b/src/Ydb.Sdk/tests/Auth/StaticAuthTests.cs
@@ -88,26 +88,26 @@ private async Task CheckAuth(string? passwordCreate, string? passwordAuth, int m
     }
 
 
-    [Fact]
+    [Fact(Timeout = 5_000)]
     public async Task GoodAuth()
     {
         await CheckAuth("test_password", "test_password");
     }
 
-    [Fact]
+    [Fact(Timeout = 5_000)]
     public async Task NoPasswordAuth()
     {
         await CheckAuth(null, null);
     }
 
-    [Fact]
+    [Fact(Timeout = 5_000)]
     public async Task WrongPassword()
     {
         await Assert.ThrowsAsync<InvalidCredentialsException>(
             async () => await CheckAuth("good_password", "wrong_password", maxRetries: 1));
     }
 
-    [Fact]
+    [Fact(Timeout = 5_000)]
     public async Task NotExistAuth()
     {
         var driverConfig = new DriverConfig(