Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unify logging to use ASP.NET default console logger #215

Merged
merged 9 commits into from
May 24, 2024
Merged
7 changes: 6 additions & 1 deletion osu.Server.Spectator.Tests/BuildUserCountUpdaterTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@

using System;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Moq;
using osu.Server.Spectator.Database;
using osu.Server.Spectator.Database.Models;
Expand All @@ -17,13 +18,17 @@ public class BuildUserCountUpdaterTest
private readonly EntityStore<MetadataClientState> clientStates;
private readonly Mock<IDatabaseFactory> databaseFactoryMock;
private readonly Mock<IDatabaseAccess> databaseAccessMock;
private readonly Mock<ILoggerFactory> loggerFactoryMock;

public BuildUserCountUpdaterTest()
{
clientStates = new EntityStore<MetadataClientState>();

databaseFactoryMock = new Mock<IDatabaseFactory>();
databaseAccessMock = new Mock<IDatabaseAccess>();
loggerFactoryMock = new Mock<ILoggerFactory>();
loggerFactoryMock.Setup(factory => factory.CreateLogger(It.IsAny<string>()))
.Returns(new Mock<ILogger>().Object);
databaseFactoryMock.Setup(df => df.GetInstance()).Returns(databaseAccessMock.Object);
}

Expand Down Expand Up @@ -53,7 +58,7 @@ public async Task TestPeriodicUpdates()
await trackUser(6, "unknown");

AppSettings.TrackBuildUserCounts = true;
var updater = new BuildUserCountUpdater(clientStates, databaseFactoryMock.Object)
var updater = new BuildUserCountUpdater(clientStates, databaseFactoryMock.Object, loggerFactoryMock.Object)
{
UpdateInterval = 50
};
Expand Down
14 changes: 10 additions & 4 deletions osu.Server.Spectator.Tests/ConcurrentConnectionLimiterTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
using System.Security.Claims;
using System.Threading.Tasks;
using Microsoft.AspNetCore.SignalR;
using Microsoft.Extensions.Logging;
using Moq;
using osu.Server.Spectator.Entities;
using osu.Server.Spectator.Hubs.Spectator;
Expand All @@ -17,6 +18,7 @@ public class ConcurrentConnectionLimiterTests
{
private readonly EntityStore<ConnectionState> connectionStates;
private readonly Mock<IServiceProvider> serviceProviderMock;
private readonly Mock<ILoggerFactory> loggerFactoryMock;
private readonly Mock<Hub> hubMock;

public ConcurrentConnectionLimiterTests()
Expand All @@ -28,6 +30,10 @@ public ConcurrentConnectionLimiterTests()
serviceProviderMock.Setup(sp => sp.GetService(It.IsAny<Type>()))
.Returns(hubContextMock.Object);

loggerFactoryMock = new Mock<ILoggerFactory>();
loggerFactoryMock.Setup(factory => factory.CreateLogger(It.IsAny<string>()))
.Returns(new Mock<ILogger>().Object);

hubMock = new Mock<Hub>();
}

Expand All @@ -44,7 +50,7 @@ public async Task TestNormalOperation()
})
}));

var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object);
var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object, loggerFactoryMock.Object);
var lifetimeContext = new HubLifetimeContext(hubCallerContextMock.Object, serviceProviderMock.Object, hubMock.Object);

bool connected = false;
Expand Down Expand Up @@ -103,7 +109,7 @@ public async Task TestConcurrencyBlocked()
})
}));

var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object);
var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object, loggerFactoryMock.Object);

var firstLifetimeContext = new HubLifetimeContext(firstContextMock.Object, serviceProviderMock.Object, hubMock.Object);
await filter.OnConnectedAsync(firstLifetimeContext, _ => Task.CompletedTask);
Expand Down Expand Up @@ -149,7 +155,7 @@ public async Task TestStaleDisconnectIsANoOp()
})
}));

var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object);
var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object, loggerFactoryMock.Object);

var firstLifetimeContext = new HubLifetimeContext(firstContextMock.Object, serviceProviderMock.Object, hubMock.Object);
await filter.OnConnectedAsync(firstLifetimeContext, _ => Task.CompletedTask);
Expand Down Expand Up @@ -189,7 +195,7 @@ public async Task TestHubDisconnectsTrackedSeparately()
})
}));

var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object);
var filter = new ConcurrentConnectionLimiter(connectionStates, serviceProviderMock.Object, loggerFactoryMock.Object);

var firstLifetimeContext = new HubLifetimeContext(firstContextMock.Object, serviceProviderMock.Object, new FirstHub());
await filter.OnConnectedAsync(firstLifetimeContext, _ => Task.CompletedTask);
Expand Down
6 changes: 5 additions & 1 deletion osu.Server.Spectator.Tests/MetadataHubTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
using Microsoft.Extensions.Caching.Distributed;
using Microsoft.Extensions.Caching.Memory;
using Microsoft.Extensions.Options;
using Microsoft.Extensions.Logging;
using Moq;
using osu.Game.Online.Metadata;
using osu.Game.Users;
Expand Down Expand Up @@ -36,8 +37,11 @@ public MetadataHubTest()
var mockDatabase = new Mock<IDatabaseAccess>();
var databaseFactory = new Mock<IDatabaseFactory>();
databaseFactory.Setup(factory => factory.GetInstance()).Returns(mockDatabase.Object);
var loggerFactoryMock = new Mock<ILoggerFactory>();
loggerFactoryMock.Setup(factory => factory.CreateLogger(It.IsAny<string>()))
.Returns(new Mock<ILogger>().Object);

hub = new MetadataHub(cache, userStates, databaseFactory.Object, new Mock<IDailyChallengeUpdater>().Object);
hub = new MetadataHub(loggerFactoryMock.Object, cache, userStates, databaseFactory.Object, new Mock<IDailyChallengeUpdater>().Object);

var mockContext = new Mock<HubCallerContext>();
mockContext.Setup(ctx => ctx.UserIdentifier).Returns(user_id.ToString());
Expand Down
6 changes: 6 additions & 0 deletions osu.Server.Spectator.Tests/Multiplayer/MultiplayerTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
using Microsoft.Extensions.Caching.Distributed;
using Microsoft.Extensions.Caching.Memory;
using Microsoft.Extensions.Options;
using Microsoft.Extensions.Logging;
using Moq;
using osu.Game.Beatmaps;
using osu.Game.Online.Multiplayer;
Expand Down Expand Up @@ -128,7 +129,12 @@ protected MultiplayerTest()
Clients.Setup(clients => clients.Group(MultiplayerHub.GetGroupId(ROOM_ID_2))).Returns(Receiver2.Object);
Clients.Setup(client => client.Caller).Returns(Caller.Object);

var loggerFactoryMock = new Mock<ILoggerFactory>();
loggerFactoryMock.Setup(factory => factory.CreateLogger(It.IsAny<string>()))
.Returns(new Mock<ILogger>().Object);

Hub = new TestMultiplayerHub(
loggerFactoryMock.Object,
new MemoryDistributedCache(Options.Create(new MemoryDistributedCacheOptions())),
Rooms,
UserStates,
Expand Down
17 changes: 10 additions & 7 deletions osu.Server.Spectator.Tests/Multiplayer/TestMultiplayerHub.cs
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@

using Microsoft.AspNetCore.SignalR;
using Microsoft.Extensions.Caching.Distributed;
using Microsoft.Extensions.Logging;
using osu.Server.Spectator.Database;
using osu.Server.Spectator.Entities;
using osu.Server.Spectator.Hubs.Multiplayer;
Expand All @@ -13,13 +14,15 @@ public class TestMultiplayerHub : MultiplayerHub
{
public new MultiplayerHubContext HubContext => base.HubContext;

public TestMultiplayerHub(IDistributedCache cache,
EntityStore<ServerMultiplayerRoom> rooms,
EntityStore<MultiplayerClientState> users,
IDatabaseFactory databaseFactory,
ChatFilters chatFilters,
IHubContext<MultiplayerHub> hubContext)
: base(cache, rooms, users, databaseFactory, chatFilters, hubContext)
public TestMultiplayerHub(
ILoggerFactory loggerFactory,
IDistributedCache cache,
EntityStore<ServerMultiplayerRoom> rooms,
EntityStore<MultiplayerClientState> users,
IDatabaseFactory databaseFactory,
ChatFilters chatFilters,
IHubContext<MultiplayerHub> hubContext)
: base(loggerFactory, cache, rooms, users, databaseFactory, chatFilters, hubContext)
{
}

Expand Down
2 changes: 1 addition & 1 deletion osu.Server.Spectator.Tests/SpectatorHubTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,7 @@ public SpectatorHubTest()

var mockScoreProcessedSubscriber = new Mock<IScoreProcessedSubscriber>();

hub = new SpectatorHub(cache, clientStates, databaseFactory.Object, scoreUploader, mockScoreProcessedSubscriber.Object);
hub = new SpectatorHub(loggerFactory.Object, cache, clientStates, databaseFactory.Object, scoreUploader, mockScoreProcessedSubscriber.Object);
}

[Fact]
Expand Down
11 changes: 8 additions & 3 deletions osu.Server.Spectator.Tests/StatefulUserHubTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,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.Online;
Expand All @@ -29,10 +30,14 @@ public class StatefulUserHubTest

public StatefulUserHubTest()
{
var loggerFactoryMock = new Mock<ILoggerFactory>();
loggerFactoryMock.Setup(factory => factory.CreateLogger(It.IsAny<string>()))
.Returns(new Mock<ILogger>().Object);

MemoryDistributedCache cache = new MemoryDistributedCache(Options.Create(new MemoryDistributedCacheOptions()));

userStates = new EntityStore<ClientState>();
hub = new TestStatefulHub(cache, userStates);
hub = new TestStatefulHub(loggerFactoryMock.Object, cache, userStates);

mockContext = new Mock<HubCallerContext>();
mockContext.Setup(context => context.UserIdentifier).Returns(user_id.ToString());
Expand Down Expand Up @@ -108,8 +113,8 @@ private void setNewConnectionId(string? connectionId = null) =>

private class TestStatefulHub : StatefulUserHub<IStatefulUserHubClient, ClientState>
{
public TestStatefulHub(IDistributedCache cache, EntityStore<ClientState> userStates)
: base(cache, userStates)
public TestStatefulHub(ILoggerFactory loggerFactory, IDistributedCache cache, EntityStore<ClientState> userStates)
: base(loggerFactory, cache, userStates)
{
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
using System.Security.Cryptography;
using Microsoft.AspNetCore.Authentication.JwtBearer;
using Microsoft.Extensions.Options;
using Microsoft.Extensions.Logging;
using Microsoft.IdentityModel.JsonWebTokens;
using Microsoft.IdentityModel.Tokens;
using Org.BouncyCastle.Crypto.Parameters;
Expand All @@ -17,10 +18,12 @@ namespace osu.Server.Spectator.Authentication
public class ConfigureJwtBearerOptions : IConfigureNamedOptions<JwtBearerOptions>
{
private readonly IDatabaseFactory databaseFactory;
private readonly ILoggerFactory loggerFactory;

public ConfigureJwtBearerOptions(IDatabaseFactory databaseFactory)
public ConfigureJwtBearerOptions(IDatabaseFactory databaseFactory, ILoggerFactory loggerFactory)
{
this.databaseFactory = databaseFactory;
this.loggerFactory = loggerFactory;
}

public void Configure(JwtBearerOptions options)
Expand Down Expand Up @@ -50,7 +53,7 @@ public void Configure(JwtBearerOptions options)

if (userId != tokenUserId)
{
Console.WriteLine("Token revoked or expired");
loggerFactory.CreateLogger("JsonWebToken").LogInformation("Token revoked or expired");
context.Fail("Token has expired or been revoked");
}
}
Expand Down
2 changes: 2 additions & 0 deletions osu.Server.Spectator/CodeAnalysis/BannedSymbols.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
T:osu.Framework.Logging.Logger;Don't use osu!framework logger. Use Microsoft.Extensions.Logging.ILogger instead through DI.
T:System.Console;Don't use Console for logging. Use Microsoft.Extensions.Logging.ILogger instead through DI.
15 changes: 11 additions & 4 deletions osu.Server.Spectator/ConcurrentConnectionLimiter.cs
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,8 @@
using System.Threading.Tasks;
using Microsoft.AspNetCore.SignalR;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using osu.Framework.Extensions.TypeExtensions;
using osu.Framework.Logging;
using osu.Game.Online;
using osu.Server.Spectator.Entities;
using osu.Server.Spectator.Extensions;
Expand All @@ -21,16 +21,19 @@ public class ConcurrentConnectionLimiter : IHubFilter
private readonly EntityStore<ConnectionState> connectionStates;

private readonly IServiceProvider serviceProvider;
private readonly ILogger logger;

private static readonly IEnumerable<Type> stateful_user_hubs
= typeof(IStatefulUserHub).Assembly.GetTypes().Where(type => typeof(IStatefulUserHub).IsAssignableFrom(type) && typeof(Hub).IsAssignableFrom(type) && !type.IsInterface && !type.IsAbstract).ToArray();

public ConcurrentConnectionLimiter(
EntityStore<ConnectionState> connectionStates,
IServiceProvider serviceProvider)
IServiceProvider serviceProvider,
ILoggerFactory loggerFactory)
{
this.connectionStates = connectionStates;
this.serviceProvider = serviceProvider;
logger = loggerFactory.CreateLogger(nameof(ConcurrentConnectionLimiter));
}

public async Task OnConnectedAsync(HubLifetimeContext context, Func<HubLifetimeContext, Task> next)
Expand Down Expand Up @@ -83,8 +86,12 @@ private async Task registerConnection(HubLifetimeContext context)
}
}

private static void log(HubLifetimeContext context, string message)
=> Logger.Log($"[user:{context.Context.GetUserId()}] [connection:{context.Context.ConnectionId}] [hub:{context.Hub.GetType().ReadableName()}] {message}");
private void log(HubLifetimeContext context, string message)
=> logger.LogInformation("[user:{user}] [connection:{connection}] [hub:{hub}] {message}",
context.Context.GetUserId(),
context.Context.ConnectionId,
context.Hub.GetType().ReadableName(),
message);

public async ValueTask<object?> InvokeMethodAsync(HubInvocationContext invocationContext, Func<HubInvocationContext, ValueTask<object?>> next)
{
Expand Down
20 changes: 14 additions & 6 deletions osu.Server.Spectator/GracefulShutdownManager.cs
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,11 @@
using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Hosting;
using osu.Framework.Logging;
using Microsoft.Extensions.Logging;
using osu.Game.Online.Multiplayer;
using osu.Server.Spectator.Entities;
using osu.Server.Spectator.Hubs;
Expand All @@ -30,6 +31,7 @@ public class GracefulShutdownManager
private readonly List<IEntityStore> dependentStores = new List<IEntityStore>();
private readonly EntityStore<ServerMultiplayerRoom> roomStore;
private readonly BuildUserCountUpdater buildUserCountUpdater;
private readonly ILogger logger;

public GracefulShutdownManager(
EntityStore<ServerMultiplayerRoom> roomStore,
Expand All @@ -38,10 +40,12 @@ public GracefulShutdownManager(
ScoreUploader scoreUploader,
EntityStore<ConnectionState> connectionStateStore,
EntityStore<MetadataClientState> metadataClientStore,
BuildUserCountUpdater buildUserCountUpdater)
BuildUserCountUpdater buildUserCountUpdater,
ILoggerFactory loggerFactory)
{
this.roomStore = roomStore;
this.buildUserCountUpdater = buildUserCountUpdater;
logger = loggerFactory.CreateLogger(nameof(GracefulShutdownManager));

dependentStores.Add(roomStore);
dependentStores.Add(clientStateStore);
Expand All @@ -58,7 +62,7 @@ public GracefulShutdownManager(

private void shutdownSafely()
{
Logger.Log("Server shutdown triggered");
logger.LogInformation("Server shutdown triggered");

// stop tracking user counts.
// it is presumed that another instance will take over doing so.
Expand All @@ -78,22 +82,26 @@ await r.StartCountdown(new ServerShuttingDownCountdown
TimeSpan timeWaited = new TimeSpan();
TimeSpan timeBetweenChecks = TimeSpan.FromSeconds(10);

var stringBuilder = new StringBuilder();

while (timeWaited < TIME_BEFORE_FORCEFUL_SHUTDOWN)
{
var remaining = dependentStores.Select(store => (store.EntityName, store.RemainingUsages));

if (remaining.Sum(s => s.RemainingUsages) == 0)
break;

Logger.Log("Waiting for usages of existing entities to finish...");
stringBuilder.Clear();
stringBuilder.AppendLine("Waiting for usages of existing entities to finish...");
foreach (var r in remaining)
Logger.Log($"{r.EntityName,10}: {r.RemainingUsages}");
stringBuilder.AppendLine($"{r.EntityName,10}: {r.RemainingUsages}");
logger.LogInformation(stringBuilder.ToString());

Thread.Sleep(timeBetweenChecks);
timeWaited = timeWaited.Add(timeBetweenChecks);
}

Logger.Log("All entities cleaned up. Server shutdown unblocking.");
logger.LogInformation("All entities cleaned up. Server shutdown unblocking.");
}

private async Task performOnAllRooms(Func<ServerMultiplayerRoom, Task> action)
Expand Down
4 changes: 2 additions & 2 deletions osu.Server.Spectator/Hubs/ILogTarget.cs
Original file line number Diff line number Diff line change
Expand Up @@ -2,13 +2,13 @@
// See the LICENCE file in the repository root for full licence text.

using System;
using osu.Framework.Logging;
using Microsoft.Extensions.Logging;

namespace osu.Server.Spectator.Hubs
{
internal interface ILogTarget
{
void Log(string message, LogLevel logLevel = LogLevel.Verbose);
void Log(string message, LogLevel logLevel = LogLevel.Information);

void Error(string message, Exception exception);
}
Expand Down
Loading