[backend/core] Add request/job id to logs, improve log formatting

This commit is contained in:
Laura Hausmann 2024-08-13 03:41:35 +02:00
parent 86a5da5418
commit dba3fc1a6a
No known key found for this signature in database
GPG key ID: D044E84C5BE01605
3 changed files with 84 additions and 28 deletions

View file

@ -1,3 +1,4 @@
using System.Diagnostics;
using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Logging.Console; using Microsoft.Extensions.Logging.Console;
@ -40,6 +41,12 @@ file static class TextWriterExtensions
ConsoleColor? foreground ConsoleColor? foreground
) )
{ {
if (!ConsoleUtils.EmitAnsiColorCodes)
{
background = null;
foreground = null;
}
if (background.HasValue) if (background.HasValue)
textWriter.Write(GetBackgroundColorEscapeCode(background.Value)); textWriter.Write(GetBackgroundColorEscapeCode(background.Value));
if (foreground.HasValue) if (foreground.HasValue)
@ -127,7 +134,7 @@ file static class ConsoleUtils
} }
} }
file sealed class CustomFormatter() : ConsoleFormatter("custom") file sealed class CustomFormatter() : ConsoleFormatter("custom"), ISupportExternalScope
{ {
private const string LoglevelPadding = ": "; private const string LoglevelPadding = ": ";
@ -136,6 +143,8 @@ file sealed class CustomFormatter() : ConsoleFormatter("custom")
private static readonly string NewLineWithMessagePadding = Environment.NewLine + MessagePadding; private static readonly string NewLineWithMessagePadding = Environment.NewLine + MessagePadding;
private IExternalScopeProvider? _scopeProvider;
public override void Write<TState>( public override void Write<TState>(
in LogEntry<TState> logEntry, in LogEntry<TState> logEntry,
IExternalScopeProvider? scopeProvider, IExternalScopeProvider? scopeProvider,
@ -144,10 +153,26 @@ file sealed class CustomFormatter() : ConsoleFormatter("custom")
{ {
var message = logEntry.Formatter(logEntry.State, logEntry.Exception); var message = logEntry.Formatter(logEntry.State, logEntry.Exception);
// ReSharper disable once ConditionIsAlwaysTrueOrFalseAccordingToNullableAPIContract // ReSharper disable once ConditionIsAlwaysTrueOrFalseAccordingToNullableAPIContract
if (logEntry.Exception == null && message == null) if (logEntry.Exception == null && message == null) return;
{
return; scopeProvider = _scopeProvider ?? scopeProvider;
} Dictionary<string, string> scopes = [];
scopeProvider?.ForEachScope((p, _) =>
{
if (p is KeyValuePair<string, string> kvp)
scopes.Add(kvp.Key, kvp.Value);
else if (p is Tuple<string, string> tuple)
scopes.Add(tuple.Item1, tuple.Item2);
else if (p is (string key, string value))
scopes.Add(key, value);
else if (p is IEnumerable<KeyValuePair<string, object>> @enum)
foreach (var item in @enum.Where(e => e.Value is string))
scopes.Add(item.Key, (string)item.Value);
},
null as object);
var scope = scopes.GetValueOrDefault("JobId") ??
scopes.GetValueOrDefault("RequestId");
var logLevel = logEntry.LogLevel; var logLevel = logEntry.LogLevel;
var logLevelColors = GetLogLevelConsoleColors(logLevel); var logLevelColors = GetLogLevelConsoleColors(logLevel);
@ -155,30 +180,29 @@ file sealed class CustomFormatter() : ConsoleFormatter("custom")
textWriter.WriteColoredMessage(logLevelString, logLevelColors.Background, logLevelColors.Foreground); textWriter.WriteColoredMessage(logLevelString, logLevelColors.Background, logLevelColors.Foreground);
CreateDefaultLogMessage(textWriter, logEntry, message); CreateDefaultLogMessage(textWriter, logEntry, message, scope);
} }
private static void CreateDefaultLogMessage<TState>( private static void CreateDefaultLogMessage<TState>(
TextWriter textWriter, in LogEntry<TState> logEntry, TextWriter textWriter, in LogEntry<TState> logEntry,
string message string message, string? scope
) )
{ {
var eventId = logEntry.EventId.Id;
var exception = logEntry.Exception; var exception = logEntry.Exception;
var singleLine = !message.Contains('\n') && exception == null; var singleLine = !message.Contains('\n') && exception == null;
textWriter.Write(LoglevelPadding); textWriter.Write(LoglevelPadding);
textWriter.Write(logEntry.Category); textWriter.WriteColoredMessage("[", null, ConsoleColor.Gray);
textWriter.Write('['); textWriter.WriteColoredMessage(scope ?? "core", null, ConsoleColor.Cyan);
textWriter.WriteColoredMessage("] ", null, ConsoleColor.Gray);
textWriter.WriteColoredMessage(logEntry.Category, null, ConsoleColor.Blue);
Span<char> span = stackalloc char[10]; if (singleLine) textWriter.WriteColoredMessage(" >", null, ConsoleColor.Gray);
if (eventId.TryFormat(span, out var charsWritten))
textWriter.Write(span[..charsWritten]);
else else
textWriter.Write(eventId.ToString()); {
textWriter.WriteColoredMessage(":", null, ConsoleColor.Gray);
textWriter.Write(']'); textWriter.Write(Environment.NewLine);
if (!singleLine) textWriter.Write(Environment.NewLine); }
WriteMessage(textWriter, message, singleLine); WriteMessage(textWriter, message, singleLine);
@ -256,12 +280,19 @@ file sealed class CustomFormatter() : ConsoleFormatter("custom")
public ConsoleColor? Foreground { get; } = foreground; public ConsoleColor? Foreground { get; } = foreground;
public ConsoleColor? Background { get; } = background; public ConsoleColor? Background { get; } = background;
} }
public void SetScopeProvider(IExternalScopeProvider scopeProvider)
{
_scopeProvider = scopeProvider;
}
} }
file sealed class CustomSystemdConsoleFormatter() : ConsoleFormatter("systemd-custom") file sealed class CustomSystemdConsoleFormatter() : ConsoleFormatter("systemd-custom"), ISupportExternalScope
{ {
private static readonly string MessagePadding = new(' ', 6); private static readonly string MessagePadding = new(' ', 6);
private IExternalScopeProvider? _scopeProvider;
public override void Write<TState>( public override void Write<TState>(
in LogEntry<TState> logEntry, in LogEntry<TState> logEntry,
IExternalScopeProvider? scopeProvider, IExternalScopeProvider? scopeProvider,
@ -272,17 +303,37 @@ file sealed class CustomSystemdConsoleFormatter() : ConsoleFormatter("systemd-cu
// ReSharper disable once ConditionIsAlwaysTrueOrFalseAccordingToNullableAPIContract // ReSharper disable once ConditionIsAlwaysTrueOrFalseAccordingToNullableAPIContract
if (logEntry.Exception == null && message == null) return; if (logEntry.Exception == null && message == null) return;
var logLevel = logEntry.LogLevel; var logLevel = logEntry.LogLevel;
var category = logEntry.Category; var category = logEntry.Category + " " + Activity.Current?.TraceId;
var id = logEntry.EventId.Id;
var exception = logEntry.Exception; var exception = logEntry.Exception;
var singleLine = !message.Contains('\n') && exception == null; var singleLine = !message.Contains('\n') && exception == null;
var syslogSeverityString = GetSyslogSeverityString(logLevel); var syslogSeverityString = GetSyslogSeverityString(logLevel);
textWriter.Write(syslogSeverityString);
textWriter.Write(category); scopeProvider = _scopeProvider ?? scopeProvider;
Dictionary<string, string> scopes = [];
scopeProvider?.ForEachScope((p, _) =>
{
if (p is KeyValuePair<string, string> kvp)
scopes.Add(kvp.Key, kvp.Value);
else if (p is Tuple<string, string> tuple)
scopes.Add(tuple.Item1, tuple.Item2);
else if (p is (string key, string value))
scopes.Add(key, value);
else if (p is IEnumerable<KeyValuePair<string, object>> @enum)
foreach (var item in @enum.Where(e => e.Value is string))
scopes.Add(item.Key, (string)item.Value);
},
null as object);
var scope = scopes.GetValueOrDefault("JobId") ??
scopes.GetValueOrDefault("RequestId");
textWriter.Write(syslogSeverityString);
textWriter.Write('['); textWriter.Write('[');
textWriter.Write(id); textWriter.Write(scope ?? "core");
textWriter.Write(']'); textWriter.Write(']');
textWriter.Write(' ');
textWriter.Write(category);
textWriter.Write(singleLine ? " >" : ":");
if (!string.IsNullOrEmpty(message)) if (!string.IsNullOrEmpty(message))
WriteMessage(textWriter, message, logLevel, singleLine); WriteMessage(textWriter, message, logLevel, singleLine);
@ -344,6 +395,11 @@ file sealed class CustomSystemdConsoleFormatter() : ConsoleFormatter("systemd-cu
_ => throw new ArgumentOutOfRangeException(nameof(logLevel)) _ => throw new ArgumentOutOfRangeException(nameof(logLevel))
}; };
} }
public void SetScopeProvider(IExternalScopeProvider scopeProvider)
{
_scopeProvider = scopeProvider;
}
} }
#endregion #endregion

View file

@ -1,6 +1,6 @@
namespace Iceshrimp.Backend.Core.Services; namespace Iceshrimp.Backend.Core.Services;
public class FollowupTaskService(IServiceScopeFactory serviceScopeFactory) public class FollowupTaskService(IServiceScopeFactory serviceScopeFactory, ILogger<FollowupTaskService> logger)
{ {
public bool IsBackgroundWorker { get; private set; } public bool IsBackgroundWorker { get; private set; }
@ -9,16 +9,15 @@ public class FollowupTaskService(IServiceScopeFactory serviceScopeFactory)
return Task.Run(async () => return Task.Run(async () =>
{ {
await using var scope = serviceScopeFactory.CreateAsyncScope(); await using var scope = serviceScopeFactory.CreateAsyncScope();
try try
{ {
var provider = scope.ServiceProvider; var instance = scope.ServiceProvider.GetRequiredService<FollowupTaskService>();
var instance = provider.GetRequiredService<FollowupTaskService>();
instance.IsBackgroundWorker = true; instance.IsBackgroundWorker = true;
await work(provider); await work(scope.ServiceProvider);
} }
catch (Exception e) catch (Exception e)
{ {
var logger = scope.ServiceProvider.GetRequiredService<ILogger<FollowupTaskService>>();
logger.LogError("Failed to execute background task {name}: {error}", taskName, e.ToString()); logger.LogError("Failed to execute background task {name}: {error}", taskName, e.ToString());
} }
}); });

View file

@ -398,6 +398,7 @@ public class PostgresJobQueue<T>(
if (await db.GetJob(name).ToListAsync(token) is not [{ } job]) if (await db.GetJob(name).ToListAsync(token) is not [{ } job])
return; return;
using var _ = _logger.BeginScope(("JobId", job.Id.ToStringLower()));
_logger.LogTrace("Processing {queue} job {id}", name, job.Id); _logger.LogTrace("Processing {queue} job {id}", name, job.Id);
var data = JsonSerializer.Deserialize<T>(job.Data); var data = JsonSerializer.Deserialize<T>(job.Data);