From ac9533695ee76db2ed9c5d108c7057947ec400e2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bart=C5=82omiej=20Dach?= Date: Thu, 1 Feb 2024 19:30:15 +0100 Subject: [PATCH] Log score uploader errors to sentry Before you open the diff, a few paragraphs of explanation. For ASP.NET Core apps, there appear to be three disparate pathways to getting events onto sentry. - The first, and most direct one, is directly calling `SentrySdk.CaptureException()`. Generally does what you'd expect it to. - The second is via `IWebHostBuilder.UseSentry()`. This is an ASP.NET-ism that works by injecting a sentry-provided middleware into the request handling stack. Thus, all requests that fail due to a thrown exception will be reported to sentry, as the middleware will catch the error, log it, and throw it back up to the rest of the ASP.NET stack to handle. However, note that *this does not apply to background workers*, as they are generally outside of this entire flow. Even if we weren't hand-rolling them via singletons instantiated in `Startup`, and instead using `IHostedService` / `BackgroundService` which is the most correct ASP.NET-ism for that, for a proper persistent background service *you can't throw exceptions because you'd kill both the background service, and the entire server with it*. - Therefore, the third method, and the one officially recommended by the sentry team for background worker use cases (https://github.com/getsentry/sentry-dotnet/issues/190#issuecomment-1491065903) is to use sentry's extension of `Sentry.Extensions.Logging`. Doing this will middleman all log calls to `Microsoft.Extensions.Logging` and push all errors (and warnings too, I believe) to sentry. In the context of all of the above, https://github.com/ppy/osu-server-spectator/pull/215 becomes doubly relevant; however, because that change requires more infra preparations and we probably want sentry logging on the replay upload process *now*, this is the minimal required change to make that happen. A side effect of this change is that the replay upload errors - which would be printed to stdout via `Console.WriteLine()` - will still be printed there, but using ASP.NET's default logging format, which is a little more... talkative, as the example below shows: fail: ScoreUploader[0] Error during score upload System.InvalidOperationException: nuh uh at osu.Server.Spectator.Storage.ThrowingScoreStorage.WriteAsync(Score score) in /home/dachb/Documents/opensource/osu-server-spectator/osu.Server.Spectator/Storage/ThrowingScoreStorage.cs:line 12 at osu.Server.Spectator.Hubs.ScoreUploader.Flush() in /home/dachb/Documents/opensource/osu-server-spectator/osu.Server.Spectator/Hubs/ScoreUploader.cs:line 117 Additionally, note that we have two *other* background workers like `ScoreUploader`, and they are: `MetadataBroadcaster` and `BuildUserCountUpdater`. I don't consider them anywhere as key as replay upload, therefore they are left as they are until we can get the full logging unification changes in. --- osu.Server.Spectator.Tests/ScoreUploaderTests.cs | 7 ++++++- osu.Server.Spectator.Tests/SpectatorHubTest.cs | 7 ++++++- osu.Server.Spectator/Hubs/ScoreUploader.cs | 12 +++++++++--- osu.Server.Spectator/Startup.cs | 1 + 4 files changed, 22 insertions(+), 5 deletions(-) diff --git a/osu.Server.Spectator.Tests/ScoreUploaderTests.cs b/osu.Server.Spectator.Tests/ScoreUploaderTests.cs index 41d9d9cf..78ca9d54 100644 --- a/osu.Server.Spectator.Tests/ScoreUploaderTests.cs +++ b/osu.Server.Spectator.Tests/ScoreUploaderTests.cs @@ -4,6 +4,7 @@ using System; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Moq; using osu.Game.Online.API.Requests.Responses; using osu.Game.Scoring; @@ -33,8 +34,12 @@ public ScoreUploaderTests() var databaseFactory = new Mock(); databaseFactory.Setup(factory => factory.GetInstance()).Returns(mockDatabase.Object); + var loggerFactory = new Mock(); + loggerFactory.Setup(factory => factory.CreateLogger(It.IsAny())) + .Returns(new Mock().Object); + mockStorage = new Mock(); - uploader = new ScoreUploader(databaseFactory.Object, mockStorage.Object); + uploader = new ScoreUploader(loggerFactory.Object, databaseFactory.Object, mockStorage.Object); uploader.UploadInterval = 1000; // Set a high timer interval for testing purposes. } diff --git a/osu.Server.Spectator.Tests/SpectatorHubTest.cs b/osu.Server.Spectator.Tests/SpectatorHubTest.cs index 0a971222..79ae7285 100644 --- a/osu.Server.Spectator.Tests/SpectatorHubTest.cs +++ b/osu.Server.Spectator.Tests/SpectatorHubTest.cs @@ -6,6 +6,7 @@ using Microsoft.AspNetCore.SignalR; using Microsoft.Extensions.Caching.Distributed; using Microsoft.Extensions.Caching.Memory; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Moq; using osu.Game.Beatmaps; @@ -61,8 +62,12 @@ public SpectatorHubTest() var databaseFactory = new Mock(); databaseFactory.Setup(factory => factory.GetInstance()).Returns(mockDatabase.Object); + var loggerFactory = new Mock(); + loggerFactory.Setup(factory => factory.CreateLogger(It.IsAny())) + .Returns(new Mock().Object); + mockScoreStorage = new Mock(); - scoreUploader = new ScoreUploader(databaseFactory.Object, mockScoreStorage.Object); + scoreUploader = new ScoreUploader(loggerFactory.Object, databaseFactory.Object, mockScoreStorage.Object); var mockScoreProcessedSubscriber = new Mock(); diff --git a/osu.Server.Spectator/Hubs/ScoreUploader.cs b/osu.Server.Spectator/Hubs/ScoreUploader.cs index adf219a2..5a4d93df 100644 --- a/osu.Server.Spectator/Hubs/ScoreUploader.cs +++ b/osu.Server.Spectator/Hubs/ScoreUploader.cs @@ -5,6 +5,7 @@ using System.Collections.Concurrent; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using osu.Game.Scoring; using osu.Server.Spectator.Database; using osu.Server.Spectator.Database.Models; @@ -31,11 +32,16 @@ public class ScoreUploader : IEntityStore, IDisposable private readonly IScoreStorage scoreStorage; private readonly CancellationTokenSource cancellationSource; private readonly CancellationToken cancellationToken; + private readonly ILogger logger; - public ScoreUploader(IDatabaseFactory databaseFactory, IScoreStorage scoreStorage) + public ScoreUploader( + ILoggerFactory loggerFactory, + IDatabaseFactory databaseFactory, + IScoreStorage scoreStorage) { this.databaseFactory = databaseFactory; this.scoreStorage = scoreStorage; + logger = loggerFactory.CreateLogger(nameof(ScoreUploader)); cancellationSource = new CancellationTokenSource(); cancellationToken = cancellationSource.Token; @@ -104,7 +110,7 @@ public async Task Flush() { if (dbScore == null) { - Console.WriteLine($"Score upload timed out for token: {item.Token}"); + logger.LogError("Score upload timed out for token: {tokenId}", item.Token); return; } @@ -127,7 +133,7 @@ public async Task Flush() } catch (Exception e) { - Console.WriteLine($"Error during score upload: {e}"); + logger.LogError(e, "Error during score upload"); } } diff --git a/osu.Server.Spectator/Startup.cs b/osu.Server.Spectator/Startup.cs index 1e19f063..b72c1ab5 100644 --- a/osu.Server.Spectator/Startup.cs +++ b/osu.Server.Spectator/Startup.cs @@ -67,6 +67,7 @@ public void ConfigureServices(IServiceCollection services) logging.ClearProviders(); logging.AddConsole(); + logging.AddSentry(); // IdentityModelEventSource.ShowPII = true; });