Skip to content

Commit

Permalink
feat(core): NethermindEth#41 improve logging
Browse files Browse the repository at this point in the history
  • Loading branch information
@chertby
chertby committed Sep 22, 2023
1 parent a303ca9 commit cb6f852
Show file tree
Hide file tree
Showing 3 changed files with 83 additions and 20 deletions.
6 changes: 3 additions & 3 deletions src/libp2p/Libp2p.Core/Channel.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -150,7 +150,7 @@ public async ValueTask<ReadOnlySequence<byte>> ReadAsync(int length,
{
anotherChunk = _bytes;
bytesToRead -= _bytes.Length;
_logger?.LogTrace("Read chunk {0} bytes", _bytes.Length);
_logger?.ReadChunk(_bytes.Length);
_bytes = default;
_read.Release();
_canWrite.Release();
Expand All @@ -159,7 +159,7 @@ public async ValueTask<ReadOnlySequence<byte>> ReadAsync(int length,
{
anotherChunk = _bytes.Slice(0, bytesToRead);
_bytes = _bytes.Slice(bytesToRead, _bytes.End);
_logger?.LogTrace("Read enough {0} bytes", anotherChunk.Length);
_logger?.ReadEnough(_bytes.Length);
bytesToRead = 0;
_canRead.Release();
}
Expand All @@ -185,7 +185,7 @@ public async ValueTask WriteAsync(ReadOnlySequence<byte> bytes)
throw new InvalidProgramException();
}

_logger?.LogTrace("Write {0} bytes", bytes.Length);
_logger?.WriteBytes(bytes.Length);

if (bytes.Length == 0)
{
Expand Down
38 changes: 21 additions & 17 deletions src/libp2p/Libp2p.Core/ChannelFactory.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,16 +24,16 @@ public ChannelFactory(IServiceProvider serviceProvider)
public IChannel SubDial(IPeerContext context, IChannelRequest? req = null)
{
IProtocol? subProtocol = req?.SubProtocol ?? SubProtocols.FirstOrDefault();

Channel chan = CreateChannel(subProtocol);
ChannelFactory? sf = _factories[subProtocol] as ChannelFactory;

_logger?.LogDebug("Dial {chan} {sf}", chan.Id, sf.SubProtocols);
_logger?.LogAction(nameof(SubDial), chan.Id, subProtocol.Id, sf?.SubProtocols.Select(protocol => protocol.Id) ?? Enumerable.Empty<string>());

_ = subProtocol.DialAsync(chan.Reverse, sf, context).ContinueWith(async t =>
{
if (!t.IsCompletedSuccessfully)
{
_logger?.LogError("Dial error {proto} via {chan}: {error}", chan.Id, subProtocol.Id, t.Exception?.Message ?? "unknown");
_logger?.LogCompletedUnsuccessfully(nameof(SubDial), chan.Id, subProtocol.Id, t.Exception, t.Exception?.Message ?? "unknown");
}
if (!chan.IsClosed)
{
Expand All @@ -50,20 +50,17 @@ public IChannel SubDial(IPeerContext context, IChannelRequest? req = null)
public IChannel SubListen(IPeerContext context, IChannelRequest? req = null)
{
IProtocol? subProtocol = req?.SubProtocol ?? SubProtocols.FirstOrDefault();
PeerContext peerContext = (PeerContext)context;

Channel chan = CreateChannel(subProtocol);
ChannelFactory? sf = _factories[subProtocol] as ChannelFactory;

_logger?.LogDebug("Listen {chan} on protocol {sp} with sub-protocols {sf}", chan.Id, subProtocol.Id, _factories[subProtocol].SubProtocols.Select(s => s.Id));
_logger?.LogAction(nameof(SubListen), chan.Id, subProtocol.Id, sf?.SubProtocols.Select(s => s.Id) ?? Enumerable.Empty<string>());

_ = subProtocol.ListenAsync(chan.Reverse, _factories[subProtocol], context).ContinueWith(async t =>
_ = subProtocol.ListenAsync(chan.Reverse, sf, context).ContinueWith(async t =>
{
if (!t.IsCompletedSuccessfully)
{
_logger?.LogError("Listen error {proto} via {chan}: {error}", subProtocol.Id, chan.Id, t.Exception?.Message ?? "unknown");
_logger?.LogCompletedUnsuccessfully(nameof(SubListen), chan.Id, subProtocol.Id, t.Exception, t.Exception?.Message ?? "unknown");
}
IEnumerable<IProtocol> dd = _factories[subProtocol].SubProtocols;

if (!chan.IsClosed)
{
await chan.CloseAsync();
Expand All @@ -80,14 +77,17 @@ public IChannel SubDialAndBind(IChannel parent, IPeerContext context,
{
IProtocol? subProtocol = req?.SubProtocol ?? SubProtocols.FirstOrDefault();
Channel chan = CreateChannel(subProtocol);
ChannelFactory? sf = _factories[subProtocol] as ChannelFactory;

_logger?.LogAction(nameof(SubDialAndBind), chan.Id, subProtocol.Id, sf?.SubProtocols.Select(s => s.Id) ?? Enumerable.Empty<string>());

chan.Bind(parent);
_ = subProtocol.DialAsync(chan.Reverse, _factories[subProtocol], context).ContinueWith(async t =>
_ = subProtocol.DialAsync(chan.Reverse, sf, context).ContinueWith(async t =>
{
if (!t.IsCompletedSuccessfully)
{
_logger?.LogError("SubDialAndBind error {proto} via {chan}: {error}", chan.Id, subProtocol.Id, t.Exception?.Message ?? "unknown");
_logger?.LogCompletedUnsuccessfully(nameof(SubDialAndBind), chan.Id, subProtocol.Id, t.Exception, t.Exception?.Message ?? "unknown");
}

if (!chan.IsClosed)
{
await chan.CloseAsync();
Expand All @@ -104,12 +104,16 @@ public IChannel SubListenAndBind(IChannel parent, IPeerContext context,
{
IProtocol? subProtocol = req?.SubProtocol ?? SubProtocols.FirstOrDefault();
Channel chan = CreateChannel(subProtocol);
ChannelFactory? sf = _factories[subProtocol] as ChannelFactory;

_logger?.LogAction(nameof(SubListenAndBind), chan.Id, subProtocol.Id, sf?.SubProtocols.Select(s => s.Id) ?? Enumerable.Empty<string>());

chan.Bind(parent);
_ = subProtocol.ListenAsync(chan.Reverse, _factories[subProtocol], context).ContinueWith(async t =>
{
if (!t.IsCompletedSuccessfully)
{
_logger?.LogError("SubListenAndBind error {proto} via {chan}: {error}", subProtocol.Id, chan.Id, t.Exception?.Message ?? "unknown");
_logger?.LogCompletedUnsuccessfully(nameof(SubListenAndBind), chan.Id, subProtocol.Id, t.Exception, t.Exception?.Message ?? "unknown");
}
if (!chan.IsClosed)
{
Expand All @@ -129,11 +133,11 @@ public ChannelFactory Setup(IProtocol parent, IDictionary<IProtocol, IChannelFac
return this;
}

private Channel CreateChannel(IProtocol subprotocol)
private Channel CreateChannel(IProtocol? subProtocol)
{
Channel chan = ActivatorUtilities.CreateInstance<Channel>(_serviceProvider);
chan.Id = $"{_parent.Id} <> {subprotocol?.Id}";
_logger?.LogDebug("Create chan {0}", chan.Id);
chan.Id = $"{_parent.Id} <> {subProtocol?.Id}";
_logger?.ChanCreated(chan.Id);
return chan;
}
}
59 changes: 59 additions & 0 deletions src/libp2p/Libp2p.Core/LogMessages.cs
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,59 @@
// SPDX-FileCopyrightText: 2023 Demerzel Solutions Limited
// SPDX-License-Identifier: MIT

using Microsoft.Extensions.Logging;

namespace Nethermind.Libp2p.Core;

internal static partial class LogMessages
{
[LoggerMessage(
Message = "Read chunk {bytes} bytes",
Level = LogLevel.Trace)]
internal static partial void ReadChunk(
this ILogger logger,
long bytes);

[LoggerMessage(
Message = "Read enough {bytes} bytes",
Level = LogLevel.Trace)]
internal static partial void ReadEnough(
this ILogger logger,
long bytes);

[LoggerMessage(
Message = "Write {bytes} bytes",
Level = LogLevel.Trace)]
internal static partial void WriteBytes(
this ILogger logger,
long bytes);

[LoggerMessage(
Message = "{method} {chan} on protocol {protocols} with sub-protocols {subProtocols}",
Level = LogLevel.Debug)]
internal static partial void LogAction(
this ILogger logger,
string method,
string chan,
string protocol,
IEnumerable<string> subProtocols);

[LoggerMessage(
Message = "Create chan {chan}",
Level = LogLevel.Debug)]
internal static partial void ChanCreated(
this ILogger logger,
string chan);

[LoggerMessage(
Message = "{method} error {protocol} via {chan}: {errorMessage}",
Level = LogLevel.Error,
SkipEnabledCheck = true)]
internal static partial void LogCompletedUnsuccessfully(
this ILogger logger,
string method,
string chan,
string protocol,
Exception? exception,
string errorMessage);
}

0 comments on commit cb6f852

Please sign in to comment.