You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@ignite.apache.org by pt...@apache.org on 2023/03/16 12:32:45 UTC
[ignite-3] branch main updated: IGNITE-19008 .NET: Improve logging (#1801)
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 60bce5341d IGNITE-19008 .NET: Improve logging (#1801)
60bce5341d is described below
commit 60bce5341d4439a5937afbb2e9f19075c58254ce
Author: Pavel Tupitsyn <pt...@apache.org>
AuthorDate: Thu Mar 16 15:32:39 2023 +0300
IGNITE-19008 .NET: Improve logging (#1801)
---
.../dotnet/Apache.Ignite.Tests/FakeServerGroup.cs | 3 ++
.../dotnet/Apache.Ignite.Tests/LoggingTests.cs | 60 ++++++++++++++++++++++
.../dotnet/Apache.Ignite.Tests/ReconnectTests.cs | 4 +-
.../Apache.Ignite/Internal/ClientFailoverSocket.cs | 12 ++++-
.../dotnet/Apache.Ignite/Internal/ClientSocket.cs | 35 ++++++++++---
.../dotnet/Apache.Ignite/Internal/Table/Table.cs | 11 ++++
.../dotnet/Apache.Ignite/Log/LoggerExtensions.cs | 24 ++++-----
7 files changed, 128 insertions(+), 21 deletions(-)
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/FakeServerGroup.cs b/modules/platforms/dotnet/Apache.Ignite.Tests/FakeServerGroup.cs
index 8481d37b6d..18e852c4fd 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/FakeServerGroup.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/FakeServerGroup.cs
@@ -47,6 +47,9 @@ public sealed class FakeServerGroup : IDisposable
}
}
+ public static FakeServerGroup Create(int count) =>
+ new(Enumerable.Range(0, count).Select(_ => new FakeServer()).ToList());
+
public static FakeServerGroup Create(int count, Func<int, FakeServer> factory) =>
new(Enumerable.Range(0, count).Select(factory).ToList());
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs b/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
new file mode 100644
index 0000000000..5dbe2fb0e6
--- /dev/null
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/LoggingTests.cs
@@ -0,0 +1,60 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+namespace Apache.Ignite.Tests;
+
+using System;
+using System.Diagnostics.CodeAnalysis;
+using System.Threading.Tasks;
+using Log;
+using NUnit.Framework;
+
+/// <summary>
+/// Logging tests.
+/// </summary>
+public class LoggingTests
+{
+ [Test]
+ [SuppressMessage("ReSharper", "AccessToDisposedClosure", Justification = "Reviewed.")]
+ public async Task TestBasicLogging()
+ {
+ var logger = new ListLogger(new ConsoleLogger { MinLevel = LogLevel.Trace });
+ logger.EnabledLevels.Clear();
+ logger.EnabledLevels.AddRange(Enum.GetValues<LogLevel>());
+
+ var cfg = new IgniteClientConfiguration { Logger = logger };
+
+ using var servers = FakeServerGroup.Create(3);
+ using (var client = await servers.ConnectClientAsync(cfg))
+ {
+ TestUtils.WaitForCondition(() => client.GetConnections().Count == 3);
+
+ await client.Tables.GetTablesAsync();
+ await client.Sql.ExecuteAsync(null, "select 1");
+ }
+
+ var log = logger.GetLogString();
+
+ StringAssert.Contains("Connection established", log);
+ StringAssert.Contains("Handshake succeeded", log);
+ StringAssert.Contains("Trying to establish secondary connections - awaiting 2 tasks", log);
+ StringAssert.Contains("All secondary connections established", log);
+ StringAssert.Contains("Sending request [opCode=3", log);
+ StringAssert.Contains("Sending request [opCode=50", log);
+ StringAssert.Contains("Connection closed", log);
+ }
+}
diff --git a/modules/platforms/dotnet/Apache.Ignite.Tests/ReconnectTests.cs b/modules/platforms/dotnet/Apache.Ignite.Tests/ReconnectTests.cs
index d7d9b9e833..57fffde958 100644
--- a/modules/platforms/dotnet/Apache.Ignite.Tests/ReconnectTests.cs
+++ b/modules/platforms/dotnet/Apache.Ignite.Tests/ReconnectTests.cs
@@ -89,7 +89,7 @@ public class ReconnectTests
ReconnectInterval = TimeSpan.FromMilliseconds(300)
};
- using var servers = FakeServerGroup.Create(10, _ => new FakeServer());
+ using var servers = FakeServerGroup.Create(10);
using var client = await servers.ConnectClientAsync(cfg);
TestUtils.WaitForCondition(() => client.GetConnections().Count == 10, 3000);
@@ -139,7 +139,7 @@ public class ReconnectTests
Logger = logger
};
- using var servers = FakeServerGroup.Create(10, _ => new FakeServer());
+ using var servers = FakeServerGroup.Create(10);
using var client = await servers.ConnectClientAsync(cfg);
Assert.DoesNotThrowAsync(async () => await client.Tables.GetTablesAsync());
diff --git a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientFailoverSocket.cs b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientFailoverSocket.cs
index 356aed71a5..d8a8c9570c 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientFailoverSocket.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientFailoverSocket.cs
@@ -270,7 +270,7 @@ namespace Apache.Ignite.Internal
}
catch (Exception e)
{
- _logger?.Warn(e, $"Failed to connect to preferred node {preferredNode}: {e.Message}");
+ _logger?.Warn(e, $"Failed to connect to preferred node [{preferredNode}]: {e.Message}");
}
}
}
@@ -559,6 +559,11 @@ namespace Apache.Ignite.Internal
{
if (!ShouldRetry(exception, op, attempt))
{
+ if (_logger?.IsEnabled(LogLevel.Debug) == true)
+ {
+ _logger.Debug($"Not retrying operation [opCode={(int)op}, opType={op}, attempt={attempt}, lastError={exception}]");
+ }
+
if (errors == null)
{
return false;
@@ -573,6 +578,11 @@ namespace Apache.Ignite.Internal
inner);
}
+ if (_logger?.IsEnabled(LogLevel.Debug) == true)
+ {
+ _logger.Debug($"Retrying operation [opCode={(int)op}, opType={op}, attempt={attempt}, lastError={exception}]");
+ }
+
if (errors == null)
{
errors = new List<Exception> { exception };
diff --git a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
index 66f9b09e19..e525862fe3 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Internal/ClientSocket.cs
@@ -175,8 +175,7 @@ namespace Apache.Ignite.Internal
if (logger?.IsEnabled(LogLevel.Debug) == true)
{
- logger.Debug(
- $"Socket connection established: {socket.LocalEndPoint} -> {socket.RemoteEndPoint}, starting handshake...");
+ logger.Debug($"Connection established [remoteAddress={socket.RemoteEndPoint}]");
}
Stream stream = new NetworkStream(socket, ownsSocket: true);
@@ -188,7 +187,8 @@ namespace Apache.Ignite.Internal
if (logger?.IsEnabled(LogLevel.Debug) == true)
{
- logger.Debug($"SSL connection established: {sslStream.NegotiatedCipherSuite}");
+ logger.Debug(
+ $"SSL connection established [remoteAddress={socket.RemoteEndPoint}]: {sslStream.NegotiatedCipherSuite}");
}
}
@@ -198,14 +198,14 @@ namespace Apache.Ignite.Internal
if (logger?.IsEnabled(LogLevel.Debug) == true)
{
- logger.Debug($"Handshake succeeded: {context}.");
+ logger.Debug($"Handshake succeeded [remoteAddress={socket.RemoteEndPoint}]: {context}.");
}
return new ClientSocket(stream, configuration, context, assignmentChangeCallback, logger);
}
catch (Exception e)
{
- logger?.Warn($"Connection failed before or during handshake: {e.Message}.", e);
+ logger?.Warn($"Connection failed before or during handshake [remoteAddress={socket.RemoteEndPoint}]: {e.Message}.", e);
// ReSharper disable once MethodHasAsyncOverload
socket.Dispose();
@@ -525,6 +525,12 @@ namespace Apache.Ignite.Internal
// Reset heartbeat timer - don't sent heartbeats when connection is active anyway.
_heartbeatTimer.Change(dueTime: _heartbeatInterval, period: TimeSpan.FromMilliseconds(-1));
+ if (_logger?.IsEnabled(LogLevel.Trace) == true)
+ {
+ _logger.Trace(
+ $"Sending request [opCode={(int)op}, remoteAddress={ConnectionContext.ClusterNode.Address}, requestId={requestId}]");
+ }
+
await _sendLock.WaitAsync(_disposeTokenSource.Token).ConfigureAwait(false);
try
@@ -607,7 +613,9 @@ namespace Apache.Ignite.Internal
if (!_requests.TryRemove(requestId, out var taskCompletionSource))
{
- var message = $"Unexpected response ID ({requestId}) received from the server, closing the socket.";
+ var message = $"Unexpected response ID ({requestId}) received from the server " +
+ $"[remoteAddress={ConnectionContext.ClusterNode.Address}], closing the socket.";
+
_logger?.Error(message);
Dispose(new IgniteClientConnectionException(ErrorGroups.Client.Protocol, message));
@@ -618,6 +626,12 @@ namespace Apache.Ignite.Internal
if (flags.HasFlag(ResponseFlags.PartitionAssignmentChanged))
{
+ if (_logger?.IsEnabled(LogLevel.Info) == true)
+ {
+ _logger.Info(
+ $"Partition assignment change notification received [remoteAddress={ConnectionContext.ClusterNode.Address}]");
+ }
+
_assignmentChangeCallback(this);
}
@@ -668,6 +682,15 @@ namespace Apache.Ignite.Internal
return;
}
+ if (ex != null)
+ {
+ _logger?.Warn(ex, $"Connection closed [remoteAddress={ConnectionContext.ClusterNode.Address}]: " + ex.Message);
+ }
+ else if (_logger?.IsEnabled(LogLevel.Debug) == true)
+ {
+ _logger.Debug($"Connection closed [remoteAddress={ConnectionContext.ClusterNode.Address}]");
+ }
+
_heartbeatTimer.Dispose();
_disposeTokenSource.Cancel();
_exception = ex;
diff --git a/modules/platforms/dotnet/Apache.Ignite/Internal/Table/Table.cs b/modules/platforms/dotnet/Apache.Ignite/Internal/Table/Table.cs
index d929994658..3c44d7af41 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Internal/Table/Table.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Internal/Table/Table.cs
@@ -25,6 +25,7 @@ namespace Apache.Ignite.Internal.Table
using Buffers;
using Ignite.Table;
using Ignite.Transactions;
+ using Log;
using Proto;
using Proto.MsgPack;
using Serialization;
@@ -50,6 +51,9 @@ namespace Apache.Ignite.Internal.Table
/** */
private readonly object _latestSchemaLock = new();
+ /** */
+ private readonly IIgniteLogger? _logger;
+
/** */
private readonly SemaphoreSlim _partitionAssignmentSemaphore = new(1);
@@ -77,6 +81,8 @@ namespace Apache.Ignite.Internal.Table
Name = name;
Id = id;
+ _logger = socket.Configuration.Logger.GetLogger(GetType());
+
RecordBinaryView = new RecordView<IIgniteTuple>(
this,
new RecordSerializer<IIgniteTuple>(this, TupleSerializerHandler.Instance),
@@ -338,6 +344,11 @@ namespace Apache.Ignite.Internal.Table
_schemas[schemaVersion] = schema;
+ if (_logger?.IsEnabled(LogLevel.Debug) == true)
+ {
+ _logger.Debug($"Schema loaded [tableId={Id}, schemaVersion={schema.Version}]");
+ }
+
lock (_latestSchemaLock)
{
if (schemaVersion > _latestSchemaVersion)
diff --git a/modules/platforms/dotnet/Apache.Ignite/Log/LoggerExtensions.cs b/modules/platforms/dotnet/Apache.Ignite/Log/LoggerExtensions.cs
index e82fc5b17f..76512e76b1 100644
--- a/modules/platforms/dotnet/Apache.Ignite/Log/LoggerExtensions.cs
+++ b/modules/platforms/dotnet/Apache.Ignite/Log/LoggerExtensions.cs
@@ -55,7 +55,7 @@ namespace Apache.Ignite.Log
/// <param name="logger">The logger.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Trace(this IIgniteLogger logger, Exception ex, string message)
+ public static void Trace(this IIgniteLogger logger, Exception? ex, string message)
{
Log(logger, LogLevel.Trace, ex, message);
}
@@ -67,7 +67,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Trace(this IIgniteLogger logger, Exception ex, string message, params object?[]? args)
+ public static void Trace(this IIgniteLogger logger, Exception? ex, string message, params object?[]? args)
{
Log(logger, LogLevel.Trace, ex, message, args);
}
@@ -99,7 +99,7 @@ namespace Apache.Ignite.Log
/// <param name="logger">The logger.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Debug(this IIgniteLogger logger, Exception ex, string message)
+ public static void Debug(this IIgniteLogger logger, Exception? ex, string message)
{
Log(logger, LogLevel.Debug, ex, message);
}
@@ -111,7 +111,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Debug(this IIgniteLogger logger, Exception ex, string message, params object?[]? args)
+ public static void Debug(this IIgniteLogger logger, Exception? ex, string message, params object?[]? args)
{
Log(logger, LogLevel.Debug, ex, message, args);
}
@@ -143,7 +143,7 @@ namespace Apache.Ignite.Log
/// <param name="logger">The logger.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Info(this IIgniteLogger logger, Exception ex, string message)
+ public static void Info(this IIgniteLogger logger, Exception? ex, string message)
{
Log(logger, LogLevel.Info, ex, message);
}
@@ -155,7 +155,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Info(this IIgniteLogger logger, Exception ex, string message, params object?[]? args)
+ public static void Info(this IIgniteLogger logger, Exception? ex, string message, params object?[]? args)
{
Log(logger, LogLevel.Info, ex, message, args);
}
@@ -187,7 +187,7 @@ namespace Apache.Ignite.Log
/// <param name="logger">The logger.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Warn(this IIgniteLogger logger, Exception ex, string message)
+ public static void Warn(this IIgniteLogger logger, Exception? ex, string message)
{
Log(logger, LogLevel.Warn, ex, message);
}
@@ -199,7 +199,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Warn(this IIgniteLogger logger, Exception ex, string message, params object?[]? args)
+ public static void Warn(this IIgniteLogger logger, Exception? ex, string message, params object?[]? args)
{
Log(logger, LogLevel.Warn, ex, message, args);
}
@@ -231,7 +231,7 @@ namespace Apache.Ignite.Log
/// <param name="logger">The logger.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Error(this IIgniteLogger logger, Exception ex, string message)
+ public static void Error(this IIgniteLogger logger, Exception? ex, string message)
{
Log(logger, LogLevel.Error, ex, message);
}
@@ -243,7 +243,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Error(this IIgniteLogger logger, Exception ex, string message, params object?[]? args)
+ public static void Error(this IIgniteLogger logger, Exception? ex, string message, params object?[]? args)
{
Log(logger, LogLevel.Error, ex, message, args);
}
@@ -282,7 +282,7 @@ namespace Apache.Ignite.Log
/// <param name="level">The level.</param>
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
- public static void Log(this IIgniteLogger logger, LogLevel level, Exception ex, string message)
+ public static void Log(this IIgniteLogger logger, LogLevel level, Exception? ex, string message)
{
IgniteArgumentCheck.NotNull(logger, "logger");
@@ -297,7 +297,7 @@ namespace Apache.Ignite.Log
/// <param name="ex">The exception.</param>
/// <param name="message">The message.</param>
/// <param name="args">The arguments.</param>
- public static void Log(this IIgniteLogger logger, LogLevel level, Exception ex, string message, params object?[]? args)
+ public static void Log(this IIgniteLogger logger, LogLevel level, Exception? ex, string message, params object?[]? args)
{
IgniteArgumentCheck.NotNull(logger, "logger");