Skip to content

Commit

Permalink
Enhance logging consistency and add custom headers (#143)
Browse files Browse the repository at this point in the history 
Co-authored-by: Foretack <[email protected]>
  • Loading branch information
@occluder
occluder and occluder authored Jan 14, 2025
1 parent 2d9a02a commit 51293e3
Show file tree
Hide file tree
Showing 6 changed files with 69 additions and 46 deletions.
21 changes: 19 additions & 2 deletions MiniTwitch.Common/DefaultMiniTwitchLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,9 @@ public class DefaultMiniTwitchLogger<T> : ILogger<T>, ILogger
{
public bool Enabled { get; set; } = true;
public LogLevel MinimumLevel { get; set; } = LogLevel.Information;
public string LoggingHeader { get; set; } = string.Empty;

private static readonly object _lock = new();
static readonly object _lock = new();

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
Expand All @@ -17,6 +18,9 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
lock (_lock)
{
Console.Write($"[{DateTimeOffset.Now:HH:mm:ss} ");
Console.ForegroundColor = ConsoleColor.Cyan;
Console.Write(LoggingHeader);
Console.Write(' ');
Console.ForegroundColor = logLevel switch
{
LogLevel.Trace => ConsoleColor.Gray,
Expand Down Expand Up @@ -48,5 +52,18 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
}
}
public bool IsEnabled(LogLevel logLevel) => this.Enabled && logLevel >= this.MinimumLevel;
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => throw new NotImplementedException();
public IDisposable? BeginScope<TState>(TState state) where TState : notnull
{
this.LoggingHeader = state.ToString() ?? "<BAD STATE>";
return new NoopDisposable(this);
}

class NoopDisposable(DefaultMiniTwitchLogger<T> logger) : IDisposable
{
readonly DefaultMiniTwitchLogger<T> _logger = logger;
public void Dispose()
{
_logger.LoggingHeader = string.Empty;
}
}
}
8 changes: 4 additions & 4 deletions MiniTwitch.Common/WebSocketClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ public async Task Start(Uri uri, CancellationToken cancellationToken = default)

// Set URI for reconnects
_uri = uri;
Log(LogLevel.Trace, "Connecting to {uri} ...", uri);
Log(LogLevel.Trace, "Connecting to {Uri} ...", uri);

// Try connecting
try
Expand Down Expand Up @@ -120,7 +120,7 @@ public async Task Restart(TimeSpan delay, CancellationToken cancellationToken =

_reconnecting = true;

Log(LogLevel.Critical, "The WebSocket client is restarting in {delay}", delay);
Log(LogLevel.Critical, "The WebSocket client is restarting in {Delay}", delay);
// Attempt to disconnect
await Disconnect(cancellationToken);

Expand Down Expand Up @@ -167,7 +167,7 @@ private async Task Receive()
}
catch (WebSocketException wse)
{
Log(LogLevel.Critical, "An error occurred while receiving data from the WebSocket connection: {msg}",
Log(LogLevel.Critical, "An error occurred while receiving data from the WebSocket connection: {Message}",
wse.Message);
break;
}
Expand Down Expand Up @@ -251,6 +251,6 @@ public async ValueTask DisposeAsync()
}

await OnDisconnect.Invoke();
Log(LogLevel.Debug, "Disposed {name}", nameof(WebSocketClient));
Log(LogLevel.Debug, "Disposed {Name}", nameof(WebSocketClient));
}
}
3 changes: 2 additions & 1 deletion MiniTwitch.Helix/Internal/HelixApiClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ internal HelixApiClient(string token, long userId, ILogger? logger, string token
_tokenValidationUrl = tokenValidationUrl;
_logger = logger;
this.UserId = userId;
GetLogger().BeginScope($"Helix-UserId={this.UserId}");
}

public void ChangeToken(string newToken, long newUserId)
Expand Down Expand Up @@ -202,6 +203,6 @@ internal async ValueTask ValidateToken(CancellationToken ct)
}
}

private void Log(LogLevel level, string template, params object[] properties) => GetLogger().Log(level, "[MiniTwitch.Helix] " + template, properties);
private void Log(LogLevel level, string template, params object[] properties) => GetLogger().Log(level, template, properties);
private ILogger GetLogger() => _logger ?? this.Logger;
}
63 changes: 33 additions & 30 deletions MiniTwitch.Irc/IrcClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -165,6 +165,7 @@ public sealed class IrcClient : IAsyncDisposable
private Uri _targetUrl = default!;
private string _loggingHeader = "[MiniTwitch:Irc-default!]";
private bool _connectInvoked;
IDisposable? _loggingScope;
#endregion

#region Init
Expand All @@ -187,13 +188,14 @@ private void InternalInit()
this.Options.CheckCredentials();

this.ExceptionHandler ??= LogEventException;
_loggingHeader = "[MiniTwitch:Irc-Anonymous]";
_loggingHeader = "Irc-User=Anonymous";
if (!this.Options.Anonymous)
{
this.Options.OAuth = Utils.CheckToken(this.Options.OAuth);
_loggingHeader = $"[MiniTwitch:Irc-{this.Options.Username}]";
_loggingHeader = $"Irc-User={this.Options.Username}";
}

_loggingScope = GetLogger().BeginScope(_loggingHeader);
OnPing += Ping;
_ws.OnDisconnect += OnWsDisconnect;
_ws.OnReconnect += OnWsReconnect;
Expand Down Expand Up @@ -266,7 +268,7 @@ private async Task OnWsReconnect()
foreach (string channel in this.JoinedChannels.Select(c => c.Name))
{
bool res = await JoinChannel(channel);
Log(LogLevel.Information, $"{(res ? "Rejoined" : "Failed to rejoin")} channel: #{{channel}}", channel);
Log(LogLevel.Information, $"{(res ? "Rejoined" : "Failed to rejoin")} channel: #{{Channel}}", channel);
await Task.Delay(joinInterval);
}
}
Expand All @@ -288,7 +290,7 @@ public async ValueTask SendRaw(string message, CancellationToken cancellationTok
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to send raw message {message}: Not connected.", message);
Log(LogLevel.Error, "Failed to send raw message {Message}: Not connected.", message);
return;
}

Expand All @@ -307,27 +309,27 @@ public async ValueTask SendMessage(string channel, string message, bool action =
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to send message {message}: Not connected.", message);
Log(LogLevel.Error, "Failed to send message {Message}: Not connected.", message);
return;
}
else if (this.Options.Anonymous)
{
Log(LogLevel.Error, "Failed to send message {message}: Cannot send message with anonymous account.", message);
Log(LogLevel.Error, "Failed to send message {Message}: Cannot send message with anonymous account.", message);
return;
}

if (nonce is not null && nonce.Contains(' '))
{
Log(LogLevel.Error, "Failed to send message {message}: Nonce cannot contain spaces.", message);
Log(LogLevel.Error, "Failed to send message {Message}: Nonce cannot contain spaces.", message);
return;
}

if (!_manager.CanSend(channel, _moderated.Contains(channel)))
{
var delay = TimeSpan.FromSeconds(90 / this.Options.MessageRateLimit);
Log(LogLevel.Debug, "Cannot send message to #{channel}: Rate limit of {count} hit. Retrying in {delay}s",
Log(LogLevel.Debug, "Cannot send message to #{Channel}: Rate limit of {Count} hit. Retrying in {Delay}s",
channel, this.Options.ModMessageRateLimit, delay.TotalSeconds);
Log(LogLevel.Warning, "#{channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {normal}/30s, mod: {mod}/30s)",
Log(LogLevel.Warning, "#{Channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {Normal}/30s, mod: {Mod}/30s)",
channel, this.Options.MessageRateLimit, this.Options.ModMessageRateLimit);
await Task.Delay(delay, cancellationToken);
await SendMessage(channel, message, action, nonce, cancellationToken);
Expand All @@ -351,22 +353,22 @@ public async ValueTask ReplyTo(Privmsg parentMessage, string message, bool actio
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to send reply {message}: Not connected.", message);
Log(LogLevel.Error, "Failed to send reply {Message}: Not connected.", message);
return;
}
else if (this.Options.Anonymous)
{
Log(LogLevel.Error, "Failed to send reply {message}: Cannot send message with anonymous account.", message);
Log(LogLevel.Error, "Failed to send reply {Message}: Cannot send message with anonymous account.", message);
return;
}

string channel = parentMessage.Channel.Name;
if (!_manager.CanSend(channel, _moderated.Contains(channel)))
{
var delay = TimeSpan.FromSeconds(90 / this.Options.MessageRateLimit);
Log(LogLevel.Debug, "Cannot send message to #{channel}: Rate limit of {count} hit. Retrying in {delay}s",
Log(LogLevel.Debug, "Cannot send message to #{Channel}: Rate limit of {Count} hit. Retrying in {Delay}s",
channel, this.Options.ModMessageRateLimit, delay.TotalSeconds);
Log(LogLevel.Warning, "#{channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {normal}/30s, mod: {mod}/30s)",
Log(LogLevel.Warning, "#{Channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {Normal}/30s, mod: {Mod}/30s)",
channel, this.Options.MessageRateLimit, this.Options.ModMessageRateLimit);

await Task.Delay(delay, cancellationToken);
Expand Down Expand Up @@ -397,21 +399,21 @@ public async ValueTask ReplyTo(string messageId, string channel, string reply, b
const string act = ".me ";
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to send reply {message}: Not connected.", messageId);
Log(LogLevel.Error, "Failed to send reply {Message}: Not connected.", messageId);
return;
}
else if (this.Options.Anonymous)
{
Log(LogLevel.Error, "Failed to send reply {message}: Cannot send message with anonymous account.", messageId);
Log(LogLevel.Error, "Failed to send reply {Message}: Cannot send message with anonymous account.", messageId);
return;
}

if (!_manager.CanSend(channel, _moderated.Contains(channel)))
{
var delay = TimeSpan.FromSeconds(90 / this.Options.MessageRateLimit);
Log(LogLevel.Debug, "Cannot send message to #{channel}: Rate limit of {count} hit. Retrying in {delay}s",
Log(LogLevel.Debug, "Cannot send message to #{Channel}: Rate limit of {Count} hit. Retrying in {Delay}s",
channel, this.Options.ModMessageRateLimit, delay.TotalSeconds);
Log(LogLevel.Warning, "#{channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {normal}/30s, mod: {mod}/30s)",
Log(LogLevel.Warning, "#{Channel}: Your message was not sent yet due to the configured messaging ratelimit (normal: {Normal}/30s, mod: {Mod}/30s)",
channel, this.Options.MessageRateLimit, this.Options.ModMessageRateLimit);
await Task.Delay(delay, cancellationToken);
await ReplyTo(messageId, channel, reply, action, cancellationToken);
Expand Down Expand Up @@ -467,13 +469,13 @@ public async Task<bool> JoinChannel(string channel, CancellationToken cancellati
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to join channel #{channel}: Not connected.", channel);
Log(LogLevel.Error, "Failed to join channel #{Channel}: Not connected.", channel);
return false;
}

if (!_manager.CanJoin())
{
Log(LogLevel.Warning, "Waiting to join #{channel}: Configured ratelimit of {rate} joins/10s is hit", channel, this.Options.JoinRateLimit);
Log(LogLevel.Warning, "Waiting to join #{Channel}: Configured ratelimit of {Rate} joins/10s is hit", channel, this.Options.JoinRateLimit);
await Task.Delay(TimeSpan.FromSeconds(30 / this.Options.JoinRateLimit), cancellationToken);
return await JoinChannel(channel, cancellationToken);
}
Expand All @@ -486,7 +488,7 @@ public async Task<bool> JoinChannel(string channel, CancellationToken cancellati
}
catch
{
Log(LogLevel.Error, "Failed to join channel #{channel}: Timed out. (Channel may have been renamed or deleted)", channel);
Log(LogLevel.Error, "Failed to join channel #{Channel}: Timed out. (Channel may have been renamed or deleted)", channel);
return false;
}
}
Expand All @@ -501,7 +503,7 @@ public async Task<bool> JoinChannels(IEnumerable<string> channels, CancellationT
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to join channels {channels}: Not connected.", string.Join(',', channels));
Log(LogLevel.Error, "Failed to join channels {Channels}: Not connected.", string.Join(',', channels));
return false;
}

Expand All @@ -524,7 +526,7 @@ public Task PartChannel(string channel, CancellationToken cancellationToken = de
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to part channel #{channel}: Not connected.", channel);
Log(LogLevel.Error, "Failed to part channel #{Channel}: Not connected.", channel);
return Task.CompletedTask;
}

Expand Down Expand Up @@ -659,8 +661,8 @@ private void HandleMessage(ref IrcMessage message)
if (!this.JoinedChannels.Contains(ircChannel))
{
this.JoinedChannels.Add(ircChannel);
Log(LogLevel.Information, "Joined #{channel}", ircChannel.Name);
Log(LogLevel.Debug, "Added #{channel} to joined channels list.", ircChannel.Name);
Log(LogLevel.Information, "Joined #{Channel}", ircChannel.Name);
Log(LogLevel.Debug, "Added #{Channel} to joined channels list.", ircChannel.Name);
}

OnChannelJoin?.Invoke(ircChannel).StepOver(this.ExceptionHandler);
Expand Down Expand Up @@ -696,8 +698,8 @@ private void HandleMessage(ref IrcMessage message)
IrcChannel channel = new(ref message);
if (this.JoinedChannels.Remove(channel))
{
Log(LogLevel.Information, "Parted #{channel}", channel.Name);
Log(LogLevel.Debug, "Removed #{channel} from joined channels list.", channel.Name);
Log(LogLevel.Information, "Parted #{Channel}", channel.Name);
Log(LogLevel.Debug, "Removed #{Channel} from joined channels list.", channel.Name);

}

Expand All @@ -708,12 +710,12 @@ private void HandleMessage(ref IrcMessage message)
Notice notice = new(ref message);
if (notice.Type == NoticeType.Msg_channel_suspended)
{
Log(LogLevel.Error, "Failed to join #{channel}: Channel does not exist anymore.", notice.Channel.Name);
Log(LogLevel.Error, "Failed to join #{Channel}: Channel does not exist anymore.", notice.Channel.Name);
_coordinator.ReleaseIfLocked(WaitableEvents.ChannelSuspended);
}
else if (notice.Type == NoticeType.Bad_auth)
{
Log(LogLevel.Critical, "Authentication failed: {message}", notice.SystemMessage);
Log(LogLevel.Critical, "Authentication failed: {Message}", notice.SystemMessage);
}

OnNotice?.Invoke(notice).StepOver(this.ExceptionHandler);
Expand All @@ -740,9 +742,9 @@ private void HandleMessage(ref IrcMessage message)

private void LogEventException(Exception ex) => LogException(ex, "🚨 Exception caught in an event:");

private void Log(LogLevel level, string template, params object[] properties) => GetLogger().Log(level, $"{_loggingHeader} " + template, properties);
private void Log(LogLevel level, string template, params object[] properties) => GetLogger().Log(level, template, properties);

private void LogException(Exception ex, string template, params object[] properties) => GetLogger().LogError(ex, $"{_loggingHeader} " + template, properties);
private void LogException(Exception ex, string template, params object[] properties) => GetLogger().LogError(ex, template, properties);
#endregion

/// <inheritdoc/>
Expand All @@ -752,5 +754,6 @@ public async ValueTask DisposeAsync()
this.JoinedChannels.Clear();
_coordinator.Dispose();
_moderated.Clear();
_loggingScope?.Dispose();
}
}
10 changes: 5 additions & 5 deletions MiniTwitch.Irc/IrcMembershipClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -179,13 +179,13 @@ public async Task JoinChannel(string channel, CancellationToken cancellationToke
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to join channel {channel}: Not connected.", channel);
Log(LogLevel.Error, "Failed to join channel {Channel}: Not connected.", channel);
return;
}

if (!_manager.CanJoin())
{
Log(LogLevel.Warning, "Waiting to join #{channel}: Configured ratelimit of {rate} joins/10s is hit", channel, _options.JoinRateLimit);
Log(LogLevel.Warning, "Waiting to join #{Channel}: Configured ratelimit of {Rate} joins/10s is hit", channel, _options.JoinRateLimit);
await Task.Delay(TimeSpan.FromSeconds(30 / _options.JoinRateLimit), cancellationToken);
await JoinChannel(channel, cancellationToken);
return;
Expand All @@ -205,7 +205,7 @@ public async Task JoinChannels(IEnumerable<string> channels, CancellationToken c
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to join channels {channels}: Not connected.", string.Join(',', channels));
Log(LogLevel.Error, "Failed to join channels {Channels}: Not connected.", string.Join(',', channels));
return;
}

Expand All @@ -224,12 +224,12 @@ public Task PartChannel(string channel, CancellationToken cancellationToken = de
{
if (!_ws.IsConnected)
{
Log(LogLevel.Error, "Failed to part channel {channel}: Not connected.", channel);
Log(LogLevel.Error, "Failed to part channel {Channel}: Not connected.", channel);
return Task.CompletedTask;
}

if (_joinedChannels.Remove(channel))
Log(LogLevel.Debug, "Removed #{channel} from joined channels list.", channel);
Log(LogLevel.Debug, "Removed #{Channel} from joined channels list.", channel);

return _ws.SendAsync($"PART #{channel}", cancellationToken: cancellationToken).AsTask();
}
Expand Down
Loading

0 comments on commit 51293e3

Please sign in to comment.