Skip to content

Commit

Permalink
added logging
Browse files Browse the repository at this point in the history
  • Loading branch information
caunt committed Sep 26, 2024
1 parent 83e63c2 commit ab26268
Show file tree
Hide file tree
Showing 10 changed files with 80 additions and 39 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,8 @@ public async ValueTask SearchChannelBuilderAsync(IPlayer player, CancellationTok
if (_found)
return;

logger.LogTrace("Searching for channel builder for a {Player} player", player);

var stream = player.Client.GetStream();
var buffer = new byte[MaxHandshakeSize];
var length = await stream.ReadAsync(buffer, cancellationToken);
Expand All @@ -34,15 +36,18 @@ public async ValueTask SearchChannelBuilderAsync(IPlayer player, CancellationTok

if (searchProtocolCodec.Result is not null)
_builder = searchProtocolCodec.Result;
else
logger.LogWarning("Channel builder not found for a {Player} player", player);

_buffer = searchProtocolCodec.Buffer;
_found = true;
}

public async ValueTask<IMinecraftChannel> BuildPlayerChannelAsync(IPlayer player, CancellationToken cancellationToken = default)
{
logger.LogTrace("Building channel for a {Player} player", player);
var channel = await BuildChannelAsync(Direction.Serverbound, player.Client.GetStream(), cancellationToken);
logger.LogDebug("Client {RemoteEndPoint} is using {ChannelTypeName} channel implementation", player.RemoteEndPoint, channel.GetType().Name);
logger.LogTrace("Client {RemoteEndPoint} is using {ChannelTypeName} channel implementation", player.RemoteEndPoint, channel.GetType().Name);

if (_buffer.Length <= 0)
return channel;
Expand All @@ -55,8 +60,9 @@ public async ValueTask<IMinecraftChannel> BuildPlayerChannelAsync(IPlayer player

public async ValueTask<IMinecraftChannel> BuildServerChannelAsync(IServer server, CancellationToken cancellationToken = default)
{
logger.LogTrace("Building channel for a {Server} server", server);
var channel = await BuildChannelAsync(Direction.Clientbound, server.CreateTcpClient().GetStream(), cancellationToken);
logger.LogDebug("Server {Name} is using {ChannelTypeName} channel implementation", server.Name, channel.GetType().Name);
logger.LogTrace("Server {Name} is using {ChannelTypeName} channel implementation", server.Name, channel.GetType().Name);

return channel;
}
Expand Down
5 changes: 3 additions & 2 deletions src/Platform/EntryPoint.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
using Serilog;
using System.Diagnostics;
using Serilog;
using Serilog.Events;
using Void.Proxy;
using Void.Proxy.API;
Expand All @@ -22,7 +23,7 @@

const int width = 165;

if (OperatingSystem.IsWindows() && Console.WindowWidth < width)
if (Debugger.IsAttached && OperatingSystem.IsWindows() && Console.WindowWidth < width)
Console.WindowWidth = width;

var configuration = new LoggerConfiguration();
Expand Down
11 changes: 9 additions & 2 deletions src/Platform/Events/EventService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -30,11 +30,12 @@ public class EventService(ILogger<EventService> logger) : IEventService
public async ValueTask ThrowAsync<T>(T @event, CancellationToken cancellationToken = default) where T : IEvent
{
var eventType = @event.GetType();
logger.LogTrace("Invoking {TypeName} event", eventType.Name);

var simpleParameters = (object[]) [@event];
var cancellableParameters = (object[]) [@event, cancellationToken];

for (var methodIndex = 0; methodIndex < _methods.Count; methodIndex++)
for (var methodIndex = _methods.Count - 1; methodIndex >= 0; methodIndex--)
{
if (_methods.Count <= methodIndex)
continue; // methods may change after event invocation
Expand All @@ -45,7 +46,7 @@ public async ValueTask ThrowAsync<T>(T @event, CancellationToken cancellationTok
if (parameters[0].ParameterType != eventType)
continue;

for (var listenerIndex = 0; listenerIndex < _listeners.Count; listenerIndex++)
for (var listenerIndex = _listeners.Count - 1; listenerIndex >= 0; listenerIndex--)
{
if (_listeners.Count <= listenerIndex)
continue; // listeners may change after event invocation
Expand Down Expand Up @@ -75,12 +76,16 @@ public async ValueTask ThrowAsync<T>(T @event, CancellationToken cancellationTok
}
}
}

logger.LogTrace("Completed invoking {TypeName} event", eventType.Name);
}

public void RegisterListeners(params IEventListener[] listeners)
{
foreach (var listener in listeners)
{
logger.LogTrace("Registering {ListenerName} event listener", listener.GetType().Name);

var methods = listener.GetType().GetMethods().Where(method => Attribute.IsDefined(method, typeof(SubscribeAttribute))).ToArray();

foreach (var method in methods)
Expand All @@ -97,6 +102,8 @@ public void UnregisterListeners(params IEventListener[] listeners)
{
foreach (var listener in listeners)
{
logger.LogTrace("Unregistering {ListenerName} event listener", listener.GetType().Name);

var assembly = listener.GetType().Assembly;

_listeners.Remove(listener);
Expand Down
3 changes: 3 additions & 0 deletions src/Platform/Links/LinkService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@ public LinkService(ILogger<LinkService> logger, IServerService servers, IEventSe

public async ValueTask ConnectPlayerAnywhereAsync(IPlayer player, CancellationToken cancellationToken = default)
{
_logger.LogTrace("Looking for a server for {Player} player", player);
var server = await _events.ThrowWithResultAsync(new PlayerSearchServerEvent { Player = player }, cancellationToken) ?? _servers.RegisteredServers.First();
await ConnectAsync(player, server, cancellationToken);
}
Expand Down Expand Up @@ -59,6 +60,8 @@ private async ValueTask ConnectAsync(IPlayer player, IServer server, Cancellatio
{
using var sync = await _lock.LockAsync(cancellationToken);

_logger.LogTrace("Connecting {Player} player to a {Server} server", player, server);

var playerChannel = await player.GetChannelAsync(cancellationToken);
var serverChannel = await player.BuildServerChannelAsync(server, cancellationToken);

Expand Down
21 changes: 18 additions & 3 deletions src/Platform/Platform.cs
Original file line number Diff line number Diff line change
Expand Up @@ -23,32 +23,41 @@ public class Platform(ILogger<Platform> logger, ISettings settings, IPluginServi

public async Task StartAsync(CancellationToken cancellationToken)
{
LoggingLevelSwitch.MinimumLevel = LogEventLevel.Debug;
LoggingLevelSwitch.MinimumLevel = LogEventLevel.Verbose;

logger.LogInformation("Starting Void proxy");
var startTime = Stopwatch.GetTimestamp();

if (Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location) is { } currentDirectory)
{
logger.LogTrace("Changing working directory to {Path}", currentDirectory);
Directory.SetCurrentDirectory(currentDirectory);
}

logger.LogInformation("Loading embedded plugins");
await plugins.LoadEmbeddedPluginsAsync(cancellationToken);
logger.LogInformation("Loading directory plugins");
await plugins.LoadPluginsAsync(cancellationToken: cancellationToken);
await events.ThrowAsync<ProxyStartingEvent>(cancellationToken);

forwardings.RegisterDefault();

logger.LogInformation("Loading settings file");
await settings.LoadAsync(cancellationToken: cancellationToken);

#if RELEASE
LoggingLevelSwitch.MinimumLevel = (LogEventLevel)settings.LogLevel;
#endif

logger.LogInformation("Registering servers from settings file");
foreach (var server in settings.Servers)
servers.RegisterServer(server);

logger.LogInformation("Starting connection listener");
_listener = new TcpListener(settings.Address, settings.Port);
_listener.Start();

logger.LogInformation("Listening for connections on port {Port}...", settings.Port);
logger.LogInformation("Connection listener started on port {Port}", settings.Port);

_backgroundTask = ExecuteAsync(hostApplicationLifetime.ApplicationStopping);

Expand All @@ -58,11 +67,12 @@ public async Task StartAsync(CancellationToken cancellationToken)

public async Task StopAsync(CancellationToken cancellationToken)
{
await events.ThrowAsync<ProxyStoppingEvent>(cancellationToken);
logger.LogInformation("Stopping proxy");
await events.ThrowAsync<ProxyStoppingEvent>(cancellationToken);

// TODO disconnect everyone here

logger.LogInformation("Awaiting completion of connection listener");
if (_backgroundTask is not null)
await _backgroundTask.ContinueWith(backgroundTask =>
{
Expand All @@ -77,10 +87,15 @@ await _backgroundTask.ContinueWith(backgroundTask =>

_listener?.Stop();

logger.LogInformation("Saving settings file");
await settings.SaveAsync(cancellationToken: cancellationToken);

await events.ThrowAsync<ProxyStoppedEvent>(cancellationToken);

logger.LogInformation("Unloading plugins");
await plugins.UnloadPluginsAsync(cancellationToken);

logger.LogInformation("Proxy stopped!");
}

public async Task ExecuteAsync(CancellationToken cancellationToken)
Expand Down
1 change: 1 addition & 0 deletions src/Platform/Players/PlayerService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,7 @@ public async ValueTask AcceptPlayerAsync(TcpClient client, CancellationToken can
{
using var sync = await _lock.LockAsync(cancellationToken);

_logger.LogTrace("Accepted client from {RemoteEndPoint}", client.Client.RemoteEndPoint);
var scope = _serviceScopeFactory.CreateAsyncScope();
var player = new Player(scope, client);

Expand Down
26 changes: 13 additions & 13 deletions src/Platform/Plugins/PluginDependencyService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ public class PluginDependencyService(ILogger<PluginDependencyService> logger) :

public string? ResolveAssemblyPath(AssemblyName assemblyName)
{
logger.LogInformation("Resolving {AssemblyName} dependency", assemblyName.Name);
logger.LogTrace("Resolving {AssemblyName} dependency", assemblyName.Name);

if (assemblyName.FullName.StartsWith(nameof(Void) + '.'))
{
Expand All @@ -38,7 +38,7 @@ public class PluginDependencyService(ILogger<PluginDependencyService> logger) :

public Stream? ResolveEmbeddedAssemblyStream(AssemblyName assemblyName)
{
logger.LogInformation("Resolving {AssemblyName} embedded dependency", assemblyName.Name);
logger.LogTrace("Resolving {AssemblyName} embedded dependency", assemblyName.Name);

if (string.IsNullOrWhiteSpace(assemblyName.Name))
return null;
Expand Down Expand Up @@ -78,7 +78,7 @@ public class PluginDependencyService(ILogger<PluginDependencyService> logger) :

if (!Directory.Exists(localPackagePath))
{
logger.LogWarning("Dependency {DependencyName} not found in the offline NuGet cache", assemblyName.Name);
logger.LogTrace("Dependency {DependencyName} not found in the offline NuGet cache", assemblyName.Name);

// some packages easily resolved with just removed suffixes
if (!assemblyName.Name.Contains('.'))
Expand Down Expand Up @@ -126,9 +126,9 @@ public class PluginDependencyService(ILogger<PluginDependencyService> logger) :
return Path.Combine(packagePath, assembly);
}
}
catch (Exception ex)
catch (Exception exception)
{
logger.LogError(ex, "Failed to resolve {DependencyName} from the offline NuGet cache", assemblyName.Name);
logger.LogError(exception, "Failed to resolve {DependencyName} from the offline NuGet cache", assemblyName.Name);
}

return null;
Expand All @@ -142,7 +142,7 @@ public class PluginDependencyService(ILogger<PluginDependencyService> logger) :

if (identity is null)
{
logger.LogWarning("Dependency {DependencyName} not found in NuGet at all", assemblyName.Name);
logger.LogTrace("Dependency {DependencyName} not found in NuGet at all", assemblyName.Name);
return null;
}

Expand Down Expand Up @@ -187,33 +187,33 @@ private async ValueTask TryDownloadNuGetPackageAsync(PackageIdentity identity, C
try
{
using var result = await PackageDownloader.GetDownloadResourceResultAsync(NuGetRepository, identity, new PackageDownloadContext(NuGetCache), NuGetPackagesPath, NullLogger.Instance, cancellationToken);
logger.LogInformation("Downloaded {PackageId} {PackageVersion}", identity.Id, identity.Version);
logger.LogTrace("Downloaded {PackageId} version {PackageVersion} dependency", identity.Id, identity.Version);
}
catch (FatalProtocolException exception)
{
logger.LogCritical("Dependency {PackageId} cannot be downloaded: {Reason}", identity.Id, exception.Message);
logger.LogError("Dependency {PackageId} cannot be downloaded: {Reason}", identity.Id, exception.Message);
}
catch (RetriableProtocolException exception)
{
logger.LogError("Dependency {PackageId} loading was cancelled: {Message}", identity.Id, exception.Message);
logger.LogWarning("Dependency {PackageId} loading was cancelled: {Message}", identity.Id, exception.Message);
}
}

private async ValueTask<PackageIdentity?> TryResolveNuGetIdentityAsync(AssemblyName assemblyName, CancellationToken cancellationToken)
{
logger.LogInformation("Looking for dependency {DependencyName} as Identity in NuGet", assemblyName.Name);
logger.LogTrace("Looking for dependency {DependencyName} as Identity in NuGet", assemblyName.Name);
var identity = await TryResolveNuGetPackageIdAsync(assemblyName, cancellationToken);

if (identity is not null)
return identity;

logger.LogInformation("Looking for dependency {DependencyName} with Search in NuGet", assemblyName.Name);
logger.LogTrace("Looking for dependency {DependencyName} with Search in NuGet", assemblyName.Name);
identity = await TryResolveNuGetPackageSearchAsync(assemblyName, cancellationToken);

if (identity is not null)
return identity;

logger.LogWarning("Dependency {DependencyName} not found in NuGet", assemblyName.Name);
logger.LogTrace("Dependency {DependencyName} not found in NuGet", assemblyName.Name);
return null;
}

Expand Down Expand Up @@ -272,7 +272,7 @@ private async ValueTask TryDownloadNuGetPackageAsync(PackageIdentity identity, C
if (result is null)
return null;

logger.LogInformation("Dependency {DependencyName} resolved with version {DependencyVersion}", result.Id, result.Version);
logger.LogTrace("Dependency {DependencyName} selected best version {DependencyVersion}", result.Id, result.Version);
return result;
}

Expand Down
Loading

0 comments on commit ab26268

Please sign in to comment.