From c5bd38034486024a7191289a25bd385306c265a9 Mon Sep 17 00:00:00 2001 From: Laura Hausmann Date: Wed, 10 Apr 2024 00:15:46 +0200 Subject: [PATCH] [backend] Improved debug logging (ISH-238) --- .../ActivityPub/ActivityFetcherService.cs | 10 ++++++---- .../Core/Federation/ActivityPub/ObjectResolver.cs | 2 ++ .../Core/Middleware/ErrorHandlerMiddleware.cs | 9 +++++---- Iceshrimp.Backend/Core/Queues/DeliverQueue.cs | 3 +-- Iceshrimp.Backend/Core/Queues/InboxQueue.cs | 14 +++++--------- Iceshrimp.Backend/Core/Services/InstanceService.cs | 7 ++++++- Iceshrimp.Backend/Core/Services/NoteService.cs | 13 +++++++++++++ Iceshrimp.Backend/Core/Services/PushService.cs | 3 +++ Iceshrimp.Backend/Core/Services/QueueService.cs | 7 ++++--- 9 files changed, 45 insertions(+), 23 deletions(-) diff --git a/Iceshrimp.Backend/Core/Federation/ActivityPub/ActivityFetcherService.cs b/Iceshrimp.Backend/Core/Federation/ActivityPub/ActivityFetcherService.cs index 821abf39..ccdbac66 100644 --- a/Iceshrimp.Backend/Core/Federation/ActivityPub/ActivityFetcherService.cs +++ b/Iceshrimp.Backend/Core/Federation/ActivityPub/ActivityFetcherService.cs @@ -41,8 +41,9 @@ public class ActivityFetcherService( return await FetchRawActivityAsync(url, actor, keypair); } - public async Task> FetchActivityAsync(string url, User actor, UserKeypair keypair) + private async Task> FetchActivityAsync(string url, User actor, UserKeypair keypair) { + logger.LogDebug("Fetching activity {url} as user {id}", url, actor.Id); var (activity, finalUri) = await FetchActivityInternal(url, actor, keypair); if (activity == null) return []; @@ -55,7 +56,8 @@ public class ActivityFetcherService( if (activityIdUri.Host != finalUri.Host) throw GracefulException.UnprocessableEntity("Activity identifier doesn't match final host"); - + + logger.LogDebug("Fetching activity {url} as user {id} (attempt 2)", activityIdUri.AbsoluteUri, actor.Id); (activity, finalUri) = await FetchActivityInternal(activityIdUri.AbsoluteUri, actor, keypair); if (activity == null) return []; @@ -138,7 +140,7 @@ public class ActivityFetcherService( } } - public async Task FetchRawActivityAsync(string url, User actor, UserKeypair keypair) + private async Task FetchRawActivityAsync(string url, User actor, UserKeypair keypair) { var request = httpRqSvc.GetSigned(url, AcceptableActivityTypes, actor, keypair).DisableAutoRedirects(); var response = await client.SendAsync(request); @@ -197,7 +199,7 @@ public class ActivityFetcherService( public async Task FetchNoteAsync(string uri, User actor) { var keypair = await db.UserKeypairs.FirstOrDefaultAsync(p => p.User == actor) ?? - throw new Exception("User has no keypair"); + throw new Exception("Actor has no keypair"); var activity = await FetchActivityAsync(uri, actor, keypair); return activity.OfType().FirstOrDefault(); } diff --git a/Iceshrimp.Backend/Core/Federation/ActivityPub/ObjectResolver.cs b/Iceshrimp.Backend/Core/Federation/ActivityPub/ObjectResolver.cs index f79307b2..2dcff4be 100644 --- a/Iceshrimp.Backend/Core/Federation/ActivityPub/ObjectResolver.cs +++ b/Iceshrimp.Backend/Core/Federation/ActivityPub/ObjectResolver.cs @@ -16,6 +16,8 @@ public class ObjectResolver( { public async Task ResolveObject(ASObjectBase baseObj, int recurse = 5, bool force = false) { + logger.LogDebug("Resolving object: {id}", baseObj.Id ?? ""); + if (baseObj is ASActivity { Object.IsUnresolved: true } activity && recurse > 0) { activity.Object = await ResolveObject(activity.Object, --recurse, force); diff --git a/Iceshrimp.Backend/Core/Middleware/ErrorHandlerMiddleware.cs b/Iceshrimp.Backend/Core/Middleware/ErrorHandlerMiddleware.cs index 94413e5a..cd5d7c27 100644 --- a/Iceshrimp.Backend/Core/Middleware/ErrorHandlerMiddleware.cs +++ b/Iceshrimp.Backend/Core/Middleware/ErrorHandlerMiddleware.cs @@ -110,11 +110,12 @@ public class ErrorHandlerMiddleware( if (!ce.SuppressLog) { if (ce.Details != null) - logger.LogDebug("Request {id} was rejected with {statusCode} {error}: {message} - {details}", - ctx.TraceIdentifier, (int)ce.StatusCode, ce.Error, ce.Message, ce.Details); + logger.LogDebug("Request {id} was rejected by {source} with {statusCode} {error}: {message} - {details}", + ctx.TraceIdentifier, ce.Source, (int)ce.StatusCode, ce.Error, ce.Message, + ce.Details); else - logger.LogDebug("Request {id} was rejected with {statusCode} {error}: {message}", - ctx.TraceIdentifier, (int)ce.StatusCode, ce.Error, ce.Message); + logger.LogDebug("Request {id} was rejected by {source} with {statusCode} {error}: {message}", + ctx.TraceIdentifier, ce.Source, (int)ce.StatusCode, ce.Error, ce.Message); } } else diff --git a/Iceshrimp.Backend/Core/Queues/DeliverQueue.cs b/Iceshrimp.Backend/Core/Queues/DeliverQueue.cs index b0a00466..a661c50b 100644 --- a/Iceshrimp.Backend/Core/Queues/DeliverQueue.cs +++ b/Iceshrimp.Backend/Core/Queues/DeliverQueue.cs @@ -7,8 +7,7 @@ using JR = System.Text.Json.Serialization.JsonRequiredAttribute; namespace Iceshrimp.Backend.Core.Queues; -public class DeliverQueue() - : PostgresJobQueue("deliver", DeliverQueueProcessorDelegateAsync, 20) +public class DeliverQueue() : PostgresJobQueue("deliver", DeliverQueueProcessorDelegateAsync, 20) { private static async Task DeliverQueueProcessorDelegateAsync( Job job, DeliverJobData jobData, IServiceProvider scope, CancellationToken token diff --git a/Iceshrimp.Backend/Core/Queues/InboxQueue.cs b/Iceshrimp.Backend/Core/Queues/InboxQueue.cs index 08376653..c67df6ca 100644 --- a/Iceshrimp.Backend/Core/Queues/InboxQueue.cs +++ b/Iceshrimp.Backend/Core/Queues/InboxQueue.cs @@ -18,19 +18,15 @@ public class InboxQueue() : PostgresJobQueue("inbox", InboxQueuePr CancellationToken token ) { - var expanded = LdHelpers.Expand(JToken.Parse(jobData.Body)); - if (expanded == null) - throw new Exception("Failed to expand ASObject"); - var obj = ASObject.Deserialize(expanded); - if (obj == null) - throw new Exception("Failed to deserialize ASObject"); + var logger = scope.GetRequiredService>(); + logger.LogDebug("Processing inbox job {id}", job.Id.ToString().ToLowerInvariant()); + var expanded = LdHelpers.Expand(JToken.Parse(jobData.Body)) ?? throw new Exception("Failed to expand ASObject"); + var obj = ASObject.Deserialize(expanded) ?? throw new Exception("Failed to deserialize ASObject"); if (obj is not ASActivity activity) throw new GracefulException("Job data is not an ASActivity", $"Type: {obj.Type}"); + logger.LogTrace("Preparation took {ms} ms", job.Duration); var apHandler = scope.GetRequiredService(); - var logger = scope.GetRequiredService>(); - - logger.LogTrace("Preparation took {ms} ms", job.Duration); await apHandler.PerformActivityAsync(activity, jobData.InboxUserId, jobData.AuthenticatedUserId); } } diff --git a/Iceshrimp.Backend/Core/Services/InstanceService.cs b/Iceshrimp.Backend/Core/Services/InstanceService.cs index e5ae3ace..32c66c16 100644 --- a/Iceshrimp.Backend/Core/Services/InstanceService.cs +++ b/Iceshrimp.Backend/Core/Services/InstanceService.cs @@ -7,7 +7,7 @@ using Microsoft.EntityFrameworkCore; namespace Iceshrimp.Backend.Core.Services; -public class InstanceService(DatabaseContext db, HttpClient httpClient) +public class InstanceService(DatabaseContext db, HttpClient httpClient, ILogger logger) { private static readonly AsyncKeyedLocker KeyedLocker = new(o => { @@ -17,6 +17,11 @@ public class InstanceService(DatabaseContext db, HttpClient httpClient) private async Task GetUpdatedInstanceMetadataAsync(string host, string webDomain) { + if (host == webDomain) + logger.LogDebug("Updating instance metadata for {host}", host); + else + logger.LogDebug("Updating instance metadata for {host} ({domain})", host, webDomain); + host = host.ToLowerInvariant(); var instance = await db.Instances.FirstOrDefaultAsync(p => p.Host == host); if (instance == null) diff --git a/Iceshrimp.Backend/Core/Services/NoteService.cs b/Iceshrimp.Backend/Core/Services/NoteService.cs index fa954c5c..24f22b2b 100644 --- a/Iceshrimp.Backend/Core/Services/NoteService.cs +++ b/Iceshrimp.Backend/Core/Services/NoteService.cs @@ -62,6 +62,8 @@ public class NoteService( bool localOnly = false ) { + logger.LogDebug("Creating note for local user {id}", user.Id); + if ((text?.Length ?? 0) + (cw?.Length ?? 0) > config.Value.CharacterLimit) throw GracefulException .BadRequest($"Text & content warning cannot exceed {config.Value.CharacterLimit} characters in total"); @@ -163,6 +165,8 @@ public class NoteService( await EnqueuePollExpiryTask(poll); } + logger.LogDebug("Inserting created note {noteId} for local user {userId} into the database", note.Id, user.Id); + await UpdateNoteCountersAsync(note, true); await db.AddAsync(note); @@ -246,6 +250,8 @@ public class NoteService( Poll? poll = null ) { + logger.LogDebug("Processing note update for note {id}", note.Id); + var noteEdit = new NoteEdit { Id = IdHelpers.GenerateSlowflakeId(), @@ -384,6 +390,8 @@ public class NoteService( public async Task DeleteNoteAsync(Note note) { + logger.LogDebug("Deleting note {id}", note.Id); + db.Update(note.User); db.Remove(note); eventSvc.RaiseNoteDeleted(this, note); @@ -669,6 +677,9 @@ public class NoteService( var emoji = await emojiSvc.ProcessEmojiAsync(note.Tags?.OfType().ToList(), actor.Host); dbNote.Emojis = emoji.Select(p => p.Id).ToList(); + logger.LogDebug("Inserting created note {noteId} for remote user {userId} into the database", note.Id, + actor.Id); + await UpdateNoteCountersAsync(dbNote, true); await db.Notes.AddAsync(dbNote); await db.SaveChangesAsync(); @@ -690,6 +701,8 @@ public class NoteService( .FirstOrDefaultAsync(p => p.Uri == note.Id); if (dbNote == null) return await ProcessNoteAsync(note, actor); + + logger.LogDebug("Processing note update {id} for note {noteId}", note.Id, dbNote.Id); if (dbNote.User != actor) throw GracefulException.UnprocessableEntity("Refusing to update note of user other than actor"); diff --git a/Iceshrimp.Backend/Core/Services/PushService.cs b/Iceshrimp.Backend/Core/Services/PushService.cs index 4ec37e4d..2e288dea 100644 --- a/Iceshrimp.Backend/Core/Services/PushService.cs +++ b/Iceshrimp.Backend/Core/Services/PushService.cs @@ -47,6 +47,9 @@ public class PushService( if (subscriptions.Count == 0) return; + logger.LogDebug("Delivering mastodon push notification {id} for user {userId}", notification.Id, + notification.Notifiee.Id); + var isSelf = notification.Notifier == notification.Notifiee; var followed = subscriptions.All(p => p.Policy != PushSubscription.PushPolicy.Followed) || diff --git a/Iceshrimp.Backend/Core/Services/QueueService.cs b/Iceshrimp.Backend/Core/Services/QueueService.cs index ce7ae2fe..1cff5f76 100644 --- a/Iceshrimp.Backend/Core/Services/QueueService.cs +++ b/Iceshrimp.Backend/Core/Services/QueueService.cs @@ -428,15 +428,16 @@ public class PostgresJobQueue( job.ExceptionMessage = e.Message; job.ExceptionSource = e.TargetSite?.DeclaringType?.FullName ?? "Unknown"; - var logger = scope.ServiceProvider.GetRequiredService>(); + var logger = scope.ServiceProvider.GetRequiredService>(); + var queueName = data is BackgroundTaskJobData ? name + $" ({data.GetType().Name})" : name; if (e is GracefulException { Details: not null } ce) { logger.LogError("Failed to process job in {queue} queue: {error} - {details}", - name, ce.Message, ce.Details); + queueName, ce.Message, ce.Details); } else { - logger.LogError(e, "Failed to process job in {queue} queue:", name); + logger.LogError(e, "Failed to process job in {queue} queue:", queueName); } }