From b76d18ed32d069340faa1ac7c645bdac1e342363 Mon Sep 17 00:00:00 2001 From: Kirill Kurdyukov Date: Fri, 16 Aug 2024 13:55:53 +0300 Subject: [PATCH] dev: more logging ado.net (#172) --- .github/workflows/slo.yml | 1 + slo/src/Internal/SloContext.cs | 2 +- src/Ydb.Sdk/src/Driver.cs | 5 ++--- src/Ydb.Sdk/src/Pool/SessionPool.cs | 20 +++++++++---------- src/Ydb.Sdk/src/Services/Query/SessionPool.cs | 14 +++++++++++-- src/Ydb.Sdk/tests/Auth/StaticAuthTests.cs | 8 ++++---- 6 files changed, 29 insertions(+), 21 deletions(-) diff --git a/.github/workflows/slo.yml b/.github/workflows/slo.yml index a3b0c4c5..1e9451c0 100644 --- 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 index f7407eff..792b7f68 100644 --- a/slo/src/Internal/SloContext.cs +++ b/slo/src/Internal/SloContext.cs @@ -11,7 +11,7 @@ public abstract class SloContext 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>(); diff --git a/src/Ydb.Sdk/src/Driver.cs b/src/Ydb.Sdk/src/Driver.cs index d4099e0d..d32b34ce 100644 --- a/src/Ydb.Sdk/src/Driver.cs +++ b/src/Ydb.Sdk/src/Driver.cs @@ -233,9 +233,8 @@ private async Task DiscoverEndpoints() var resultProto = response.Operation.Result.Unpack(); - _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 index aff5f7a5..dcc98c52 100644 --- 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 where TSession : SessionBase { - private readonly ILogger> _logger; private readonly SemaphoreSlim _semaphore; private readonly ConcurrentQueue _idleSessions = new(); private readonly int _size; + protected readonly ILogger> Logger; + private volatile int _waitingCount; private volatile bool _disposed; protected SessionPool(ILogger> logger, int? maxSessionPool = null) { - _logger = logger; + Logger = logger; _size = maxSessionPool ?? 100; _semaphore = new SemaphoreSlim(_size); } @@ -41,6 +42,8 @@ internal async Task GetSession() if (session != null) // not active { + Logger.LogDebug("Session[{Id}] isn't active, creating new session", session.SessionId); + _ = DeleteNotActiveSession(session); } @@ -48,16 +51,11 @@ internal async Task GetSession() { 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 ExecOnSession(Func> 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 index a1d3dc7e..8615a4e8 100644 --- 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 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 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 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 index 110f21e3..9e54a474 100644 --- 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( async () => await CheckAuth("good_password", "wrong_password", maxRetries: 1)); } - [Fact] + [Fact(Timeout = 5_000)] public async Task NotExistAuth() { var driverConfig = new DriverConfig(