This is an automated email from the ASF dual-hosted git repository.
ptupitsyn pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/ignite-3.git
The following commit(s) were added to refs/heads/main by this push:
new 84dfe6d6f12 IGNITE-27129 .NET: Improve logging in tests (#7034)
84dfe6d6f12 is described below
commit 84dfe6d6f12acdd85a6859fae131df6c03a19cfa
Author: Pavel Tupitsyn <[email protected]>
AuthorDate: Fri Nov 21 17:00:05 2025 +0200
IGNITE-27129 .NET: Improve logging in tests (#7034)
* Improve `ConsoleLogger` to collect messages from all threads during a
given test and flush in `TearDown`
* Improve response log messages - include duration and op code
---
.../Apache.Ignite.Tests/Compute/ComputeTests.cs | 4 ++-
.../dotnet/Apache.Ignite.Tests/ConsoleLogger.cs | 34 ++++++++++++++-------
.../dotnet/Apache.Ignite.Tests/IgniteTestsBase.cs | 22 ++++++++++----
.../dotnet/Apache.Ignite.Tests/LoggingTests.cs | 2 +-
.../PartitionAwarenessRealClusterTests.cs | 4 ++-
.../dotnet/Apache.Ignite.Tests/TestUtils.cs | 6 +++-
.../dotnet/Apache.Ignite/Internal/ClientSocket.cs | 35 +++++++++++++++-------
.../dotnet/Apache.Ignite/Internal/LogMessages.cs | 4 +--
8 files changed, 80 insertions(+), 31 deletions(-)
diff --git
a/modules/platforms/dotnet/Apache.Ignite.Tests/Compute/ComputeTests.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/Compute/ComputeTests.cs
index 0f9bf019b98..823b3509769 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/Compute/ComputeTests.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/Compute/ComputeTests.cs
@@ -34,6 +34,7 @@ namespace Apache.Ignite.Tests.Compute
using Internal.Compute;
using Internal.Network;
using Internal.Proto;
+ using Microsoft.Extensions.Logging;
using Network;
using NodaTime;
using NUnit.Framework;
@@ -295,8 +296,9 @@ namespace Apache.Ignite.Tests.Compute
[TestCase(11, 4)]
public async Task TestExecuteColocated(long key, int nodeIdx)
{
+ using var loggerFactory = new ConsoleLogger(LogLevel.Trace);
var proxies = GetProxies();
- using var client = await
IgniteClient.StartAsync(GetConfig(proxies));
+ using var client = await
IgniteClient.StartAsync(GetConfig(proxies, loggerFactory));
client.WaitForConnections(proxies.Count);
var keyTuple = new IgniteTuple { [KeyCol] = key };
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/ConsoleLogger.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/ConsoleLogger.cs
index e51e7a657df..d1d47dd0016 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/ConsoleLogger.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/ConsoleLogger.cs
@@ -18,31 +18,35 @@
namespace Apache.Ignite.Tests;
using System;
+using System.Collections.Concurrent;
using System.Globalization;
using System.Text;
using Microsoft.Extensions.Logging;
/// <summary>
-/// Console logger for tests. We don't use <see
cref="Microsoft.Extensions.Logging.Console.ConsoleLogger"/> because it is
asynchronous,
-/// which means the log messages may not correspond to the current test.
+/// Console logger for tests.
/// </summary>
public class ConsoleLogger : ILogger, ILoggerFactory
{
private readonly string _categoryName;
private readonly LogLevel _minLevel;
+ private readonly ConcurrentQueue<string> _entries;
public ConsoleLogger(LogLevel minLevel)
- : this(string.Empty, minLevel)
+ : this(new(), string.Empty, minLevel)
{
// No-op.
}
- public ConsoleLogger(string categoryName, LogLevel minLevel)
+ private ConsoleLogger(ConcurrentQueue<string> entries, string
categoryName, LogLevel minLevel)
{
+ _entries = entries;
_categoryName = categoryName;
_minLevel = minLevel;
}
+ public bool AutoFlush { get; set; }
+
public void Log<TState>(
LogLevel logLevel,
EventId eventId,
@@ -69,7 +73,20 @@ public class ConsoleLogger : ILogger, ILoggerFactory
sb.AppendFormat(CultureInfo.InvariantCulture, " (exception: {0})",
exception);
}
- Console.WriteLine(sb.ToString());
+ _entries.Enqueue(sb.ToString());
+
+ if (AutoFlush)
+ {
+ Flush();
+ }
+ }
+
+ public void Flush()
+ {
+ while (_entries.TryDequeue(out var s))
+ {
+ Console.WriteLine(s);
+ }
}
public bool IsEnabled(LogLevel logLevel) => logLevel >= _minLevel;
@@ -78,12 +95,9 @@ public class ConsoleLogger : ILogger, ILoggerFactory
where TState : notnull
=> new DisposeAction(() => { });
- public void Dispose()
- {
- // No-op.
- }
+ public void Dispose() => Flush();
- public ILogger CreateLogger(string categoryName) => new
ConsoleLogger(categoryName, _minLevel);
+ public ILogger CreateLogger(string categoryName) => new
ConsoleLogger(_entries, categoryName, _minLevel);
public void AddProvider(ILoggerProvider provider) => throw new
NotSupportedException();
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/IgniteTestsBase.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/IgniteTestsBase.cs
index dd6ff0b1277..dd9e1ca80ba 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/IgniteTestsBase.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/IgniteTestsBase.cs
@@ -69,6 +69,8 @@ namespace Apache.Ignite.Tests
private TestEventListener _eventListener = null!;
+ private ConsoleLogger _logger = null!;
+
static IgniteTestsBase()
{
ServerNode = JavaServer.StartAsync().GetAwaiter().GetResult();
@@ -100,8 +102,9 @@ namespace Apache.Ignite.Tests
public async Task OneTimeSetUp()
{
_eventListener = new TestEventListener();
+ _logger = new ConsoleLogger(LogLevel.Trace);
- Client = await IgniteClient.StartAsync(GetConfig());
+ Client = await IgniteClient.StartAsync(GetConfig(_logger));
Table = (await Client.Tables.GetTableAsync(TableName))!;
TupleView = Table.RecordBinaryView;
@@ -117,6 +120,8 @@ namespace Apache.Ignite.Tests
var tableAllColumnsSql = await
Client.Tables.GetTableAsync(TableAllColumnsSqlName);
PocoAllColumnsSqlView =
tableAllColumnsSql!.GetRecordView<PocoAllColumnsSql>();
PocoAllColumnsSqlNullableView =
tableAllColumnsSql.GetRecordView<PocoAllColumnsSqlNullable>();
+
+ _logger.Flush();
}
[OneTimeTearDown]
@@ -130,11 +135,13 @@ namespace Apache.Ignite.Tests
CheckPooledBufferLeak();
_eventListener.Dispose();
+ _logger.Dispose();
}
[SetUp]
public void SetUp()
{
+ _logger.Flush();
Console.WriteLine("SetUp: " +
TestContext.CurrentContext.Test.Name);
TestUtils.CheckByteArrayPoolLeak();
}
@@ -142,6 +149,9 @@ namespace Apache.Ignite.Tests
[TearDown]
public void TearDown()
{
+ // Flush here so events from all threads are captured as current
test output.
+ _logger.Flush();
+
Console.WriteLine("TearDown start: " +
TestContext.CurrentContext.Test.Name);
_disposables.ForEach(x => x.Dispose());
@@ -149,6 +159,8 @@ namespace Apache.Ignite.Tests
CheckPooledBufferLeak();
+ _logger.Flush();
+
Console.WriteLine("TearDown end: " +
TestContext.CurrentContext.Test.Name);
}
@@ -180,20 +192,20 @@ namespace Apache.Ignite.Tests
protected static ValPoco GetValPoco(string? val) => new() { Val = val
};
- protected static IgniteClientConfiguration GetConfig() => new()
+ protected static IgniteClientConfiguration GetConfig(ILoggerFactory?
loggerFactory = null) => new()
{
Endpoints =
{
"127.0.0.1:" + ServerNode.Port,
"127.0.0.1:" + (ServerNode.Port + 1)
},
- LoggerFactory = TestUtils.GetConsoleLoggerFactory(LogLevel.Trace)
+ LoggerFactory = loggerFactory ??
TestUtils.GetConsoleLoggerFactory(LogLevel.Trace)
};
- protected static IgniteClientConfiguration
GetConfig(IEnumerable<IgniteProxy> proxies) =>
+ protected static IgniteClientConfiguration
GetConfig(IEnumerable<IgniteProxy> proxies, ILoggerFactory loggerFactory) =>
new(proxies.Select(x => x.Endpoint).ToArray())
{
- LoggerFactory =
TestUtils.GetConsoleLoggerFactory(LogLevel.Trace)
+ LoggerFactory = loggerFactory
};
protected List<IgniteProxy> GetProxies()
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
index 14304e9ad58..9140a590ba5 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
@@ -65,7 +65,7 @@ public class LoggingTests
StringAssert.Contains("[Debug] Connection established", log);
StringAssert.Contains("[Debug] Handshake succeeded [remoteAddress=[",
log);
StringAssert.Contains("[Trace] Sending request [requestId=1,
op=TablesGet, remoteAddress=", log);
- StringAssert.Contains("[Trace] Received response [requestId=1,
flags=PartitionAssignmentChanged, remoteAddress=", log);
+ StringAssert.Contains("[Trace] Received response [requestId=1,
op=TablesGet, flags=PartitionAssignmentChanged, remoteAddress=", log);
StringAssert.Contains("op=SqlExec", log);
StringAssert.Contains("[Debug] Connection closed gracefully", log);
StringAssert.DoesNotContain("[Error]", log);
diff --git
a/modules/platforms/dotnet/Apache.Ignite.Tests/PartitionAwarenessRealClusterTests.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/PartitionAwarenessRealClusterTests.cs
index d4fd6e32e47..1a4cea36428 100644
---
a/modules/platforms/dotnet/Apache.Ignite.Tests/PartitionAwarenessRealClusterTests.cs
+++
b/modules/platforms/dotnet/Apache.Ignite.Tests/PartitionAwarenessRealClusterTests.cs
@@ -23,6 +23,7 @@ using Compute;
using Ignite.Compute;
using Ignite.Table;
using Internal.Proto;
+using Microsoft.Extensions.Logging;
using NUnit.Framework;
/// <summary>
@@ -39,8 +40,9 @@ public class PartitionAwarenessRealClusterTests :
IgniteTestsBase
[Test]
public async Task TestPutRoutesRequestToPrimaryNode([Values(true, false)]
bool withTx)
{
+ using var loggerFactory = new ConsoleLogger(LogLevel.Trace);
var proxies = GetProxies();
- using var client = await IgniteClient.StartAsync(GetConfig(proxies));
+ using var client = await IgniteClient.StartAsync(GetConfig(proxies,
loggerFactory));
var recordView = (await
client.Tables.GetTableAsync(TableName))!.RecordBinaryView;
client.WaitForConnections(proxies.Count);
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/TestUtils.cs
b/modules/platforms/dotnet/Apache.Ignite.Tests/TestUtils.cs
index 96a59ccd879..3729ba48132 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/TestUtils.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/TestUtils.cs
@@ -101,7 +101,11 @@ namespace Apache.Ignite.Tests
public static bool IsRecordClass(this Type type) =>
type.GetMethods().Any(m => m.Name == "<Clone>$" && m.ReturnType ==
type);
- public static ILoggerFactory GetConsoleLoggerFactory(LogLevel
minLevel) => new ConsoleLogger(minLevel);
+ public static ILoggerFactory GetConsoleLoggerFactory(LogLevel
minLevel, bool autoFlush = true) =>
+ new ConsoleLogger(minLevel)
+ {
+ AutoFlush = autoFlush
+ };
public static void CheckByteArrayPoolLeak(int timeoutMs = 1000)
{
diff --git a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
index 8210f364397..38a61e817bc 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
@@ -75,7 +75,7 @@ namespace Apache.Ignite.Internal
private readonly IgniteClientConfigurationInternal _config;
/** Current async operations, map from request id. */
- private readonly ConcurrentDictionary<long,
TaskCompletionSource<PooledBuffer>> _requests = new();
+ private readonly ConcurrentDictionary<long, PendingRequest> _requests
= new();
/** Current notification handlers, map from request id. */
private readonly ConcurrentDictionary<long, NotificationHandler>
_notificationHandlers = new();
@@ -684,7 +684,7 @@ namespace Apache.Ignite.Internal
var requestId = Interlocked.Increment(ref _requestId);
var taskCompletionSource = new
TaskCompletionSource<PooledBuffer>();
- _requests[requestId] = taskCompletionSource;
+ _requests[requestId] = new PendingRequest(taskCompletionSource,
Stopwatch.GetTimestamp(), clientOp);
NotificationHandler? notificationHandler = null;
if (expectNotifications)
@@ -903,12 +903,19 @@ namespace Apache.Ignite.Internal
var requestId = reader.ReadInt64();
var flags = (ResponseFlags)reader.ReadInt32();
- _logger.LogReceivedResponseTrace(requestId, flags,
ConnectionContext.ClusterNode.Address);
+ var isServerOp = (flags & ResponseFlags.ServerOp) != 0;
+ var isError = (flags & ResponseFlags.Error) != 0;
+ var isNotification = (flags & ResponseFlags.Notification) != 0;
+
+ if (isServerOp || isNotification)
+ {
+ _logger.LogReceivedResponseTrace(requestId, ClientOp.None,
flags, ConnectionContext.ClusterNode.Address, null);
+ }
HandlePartitionAssignmentChange(flags, ref reader);
HandleObservableTimestamp(ref reader);
- if ((flags & ResponseFlags.ServerOp) != 0)
+ if (isServerOp)
{
Debug.Assert((flags & ResponseFlags.Error) == 0, "Server op
should not have an exception.");
var serverOp = (ServerOp)reader.ReadInt32();
@@ -917,15 +924,15 @@ namespace Apache.Ignite.Internal
return QueueServerOp(requestId, serverOp, response);
}
- var exception = (flags & ResponseFlags.Error) != 0 ? ReadError(ref
reader) : null;
+ var exception = isError ? ReadError(ref reader) : null;
response.Position += reader.Consumed;
- if ((flags & ResponseFlags.Notification) != 0)
+ if (isNotification)
{
return HandleNotification(requestId, exception, response);
}
- if (!_requests.TryRemove(requestId, out var taskCompletionSource))
+ if (!_requests.TryRemove(requestId, out var pendingReq))
{
var message = $"Unexpected response ID ({requestId}) received
from the server " +
$"[remoteAddress={ConnectionContext.ClusterNode.Address}], closing the socket.";
@@ -934,19 +941,22 @@ namespace Apache.Ignite.Internal
throw new
IgniteClientConnectionException(ErrorGroups.Client.Protocol, message);
}
+ _logger.LogReceivedResponseTrace(
+ requestId, pendingReq.Op, flags,
ConnectionContext.ClusterNode.Address,
Stopwatch.GetElapsedTime(pendingReq.StartTs));
+
Metrics.RequestsActiveDecrement();
if (exception != null)
{
AddFailedRequest();
- taskCompletionSource.TrySetException(exception);
+ pendingReq.TaskCompletionSource.TrySetException(exception);
return false;
}
Metrics.RequestsCompleted.Add(1, MetricsContext.Tags);
- return taskCompletionSource.TrySetResult(response);
+ return pendingReq.TaskCompletionSource.TrySetResult(response);
}
/// <summary>
@@ -1061,7 +1071,7 @@ namespace Apache.Ignite.Internal
{
if (_requests.TryRemove(reqId, out var req))
{
- req.TrySetException(ex);
+ req.TaskCompletionSource.TrySetException(ex);
Metrics.RequestsActiveDecrement();
}
}
@@ -1085,5 +1095,10 @@ namespace Apache.Ignite.Internal
}
}
}
+
+ private readonly record struct PendingRequest(
+ TaskCompletionSource<PooledBuffer> TaskCompletionSource,
+ long StartTs,
+ ClientOp Op);
}
}
diff --git a/modules/platforms/dotnet/Apache.Ignite/Internal/LogMessages.cs
b/modules/platforms/dotnet/Apache.Ignite/Internal/LogMessages.cs
index de6ff5e182d..e7ddc7aa75b 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Internal/LogMessages.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Internal/LogMessages.cs
@@ -200,11 +200,11 @@ internal static partial class LogMessages
this ILogger logger, string retrying, int op, ClientOp opType, int
attempt, string lastErrorMessage);
[LoggerMessage(
- Message = "Received response [requestId={RequestId}, flags={Flags},
remoteAddress={RemoteAddress}]",
+ Message = "Received response [requestId={RequestId}, op={Op},
flags={Flags}, remoteAddress={RemoteAddress}, duration={Duration}]",
Level = LogLevel.Trace,
EventId = 1027)]
internal static partial void LogReceivedResponseTrace(
- this ILogger logger, long requestId, ResponseFlags flags, EndPoint
remoteAddress);
+ this ILogger logger, long requestId, ClientOp op, ResponseFlags flags,
EndPoint remoteAddress, TimeSpan? duration);
[LoggerMessage(
Message = "Failed to send server op response [requestId={RequestId},
message={Message}]",
