Invocation Logging (#35)

src/NexNet.Generator/NexusGenerator.Emitter.cs

@@ -107,7 +107,7 @@ namespace {{Symbol.ContainingNamespace}}
     /// <summary>
     /// Nexus used for handling all {{EmitServerClientName()}} communications.
     /// </summary>
-    partial class {{TypeName}} : global::NexNet.Invocation.{{EmitServerClientName()}}NexusBase<{{this.Namespace}}.{{TypeName}}.{{this.ProxyInterface.ProxyImplName}}>, {{this.NexusInterface.Namespace}}.{{this.NexusInterface.TypeName}}, global::NexNet.Invocation.IInvocationMethodHash
+    partial class {{TypeName}} : global::NexNet.Invocation.{{EmitServerClientName()}}NexusBase<{{this.Namespace}}.{{this.TypeName}}.{{this.ProxyInterface.ProxyImplName}}>, {{this.NexusInterface.Namespace}}.{{this.NexusInterface.TypeName}}, global::NexNet.Invocation.IInvocationMethodHash
     {
 """);
         if (NexusAttribute.IsServer)
@@ -261,12 +261,16 @@ public void EmitNexusInvocation(StringBuilder sb, InvocationInterfaceMeta proxyI
             sb.AppendLine(");");
         }
 
-        sb.Append("                        ");
+        sb.Append("                        this.Context.Logger?.Log(global::NexNet.Logging.NexusLogLevel.Information, this.Context.Logger.Category, null, $\"Invoking Method: ");
 
+        EmitNexusMethodInvocation(sb, true);
+        sb.AppendLine("\");");
+        sb.Append("                        ");
+
         // Ignore the return value if we are a void method or a duplex pipe method
         if (IsReturnVoid)
         {
-            EmitNexusMethodInvocation(sb);
+            EmitNexusMethodInvocation(sb, false);
         }
         else if (IsAsync)
         {
@@ -275,12 +279,12 @@ public void EmitNexusInvocation(StringBuilder sb, InvocationInterfaceMeta proxyI
             if (IsAsync && ReturnType == null)
             {
                 sb.Append("await ");
-                EmitNexusMethodInvocation(sb);
+                EmitNexusMethodInvocation(sb, false);
             }
             else
             {
                 sb.Append("var result = await ");
-                EmitNexusMethodInvocation(sb);
+                EmitNexusMethodInvocation(sb, false);
                 sb.AppendLine("""
                         if (returnBuffer != null)
                             global::MemoryPack.MemoryPackSerializer.Serialize(returnBuffer, result);
@@ -293,7 +297,7 @@ public void EmitNexusInvocation(StringBuilder sb, InvocationInterfaceMeta proxyI
     /// Emits the invocation of the method on the nexus.
     /// </summary>
     /// <param name="sb"></param>
-    public void EmitNexusMethodInvocation(StringBuilder sb)
+    public void EmitNexusMethodInvocation(StringBuilder sb, bool writeParamNames)
     {
         sb.Append(this.Name).Append("(");
 
@@ -305,42 +309,95 @@ public void EmitNexusMethodInvocation(StringBuilder sb)
             // otherwise we need to pass the serialized value.
             if (methodParameterMeta.IsDuplexPipe)
             {
-                sb.Append("duplexPipe, ");
+                if (writeParamNames)
+                {
+                    sb.Append(methodParameterMeta.Name)
+                        .Append(" = {arguments.Item")
+                        .Append(DuplexPipeParameter!.SerializedId)
+                        .Append("}, ");
+                }
+                else
+                {
+                    sb.Append("duplexPipe, ");
+                }
+
                 addedParam = true;
             }
             else if (methodParameterMeta.IsDuplexUnmanagedChannel)
             {
-                sb.Append("global::NexNet.Pipes.NexusDuplexPipeExtensions.GetUnmanagedChannel<");
-                sb.Append(methodParameterMeta.ChannelType);
-                sb.Append(">(duplexPipe), ");
+                if (writeParamNames)
+                {
+                    sb.Append(methodParameterMeta.Name)
+                        .Append(" = {arguments.Item")
+                        .Append(DuplexPipeParameter!.SerializedId)
+                        .Append("}, ");
+                }
+                else
+                {
+                    sb.Append("global::NexNet.Pipes.NexusDuplexPipeExtensions.GetUnmanagedChannel<");
+                    sb.Append(methodParameterMeta.ChannelType);
+                    sb.Append(">(duplexPipe), ");
+                }
+
                 addedParam = true;
             }
             else if (methodParameterMeta.IsDuplexChannel)
             {
-                sb.Append("global::NexNet.Pipes.NexusDuplexPipeExtensions.GetChannel<");
-                sb.Append(methodParameterMeta.ChannelType);
-                sb.Append(">(duplexPipe), ");
+                if (writeParamNames)
+                {
+                    sb.Append(methodParameterMeta.Name)
+                        .Append(" = {arguments.Item")
+                        .Append(DuplexPipeParameter!.SerializedId)
+                        .Append("}, ");
+                }
+                else
+                {
+                    sb.Append("global::NexNet.Pipes.NexusDuplexPipeExtensions.GetChannel<");
+                    sb.Append(methodParameterMeta.ChannelType);
+                    sb.Append(">(duplexPipe), ");
+                }
+
                 addedParam = true;
             }
             else if (methodParameterMeta.SerializedValue != null)
             {
-                sb.Append("arguments.Item").Append(methodParameterMeta.SerializedId).Append(", ");
+                if (writeParamNames)
+                {
+                    sb.Append(methodParameterMeta.Name)
+                        .Append(" = {arguments.Item")
+                        .Append(methodParameterMeta.SerializedId)
+                        .Append("}, ");
+                }
+                else
+                {
+                    sb.Append("arguments.Item").Append(methodParameterMeta.SerializedId).Append(", ");
+                }
+
                 addedParam = true;
             }
         }
 
         if (CancellationTokenParameter != null)
         {
-            sb.Append("cts.Token");
+            if (writeParamNames)
+            {
+                sb.Append(CancellationTokenParameter.Name).Append(" = ct");
+            }
+            else
+            {
+                sb.Append("cts.Token");
+            }
         }
         else
         {
             if(addedParam)
                 sb.Remove(sb.Length - 2, 2);
         }
 
+        sb.Append(");");
 
-        sb.AppendLine(");");
+        if (!writeParamNames)
+            sb.AppendLine();
     }
 
     public void EmitProxyMethodInvocation(StringBuilder sb)
@@ -375,11 +432,12 @@ public void EmitProxyMethodInvocation(StringBuilder sb)
 
         sb.AppendLine(")");
         sb.AppendLine("             {");
-
+        sb.AppendLine("                 var __proxyInvoker = global::System.Runtime.CompilerServices.Unsafe.As<global::NexNet.Invocation.IProxyInvoker>(this);");
         if (SerializedParameters > 0)
         {
             sb.Append("                 var __proxyInvocationArguments = new global::System.ValueTuple<");
 
+
             foreach (var p in Parameters)
             {
                 if(p.SerializedType == null)
@@ -404,6 +462,29 @@ public void EmitProxyMethodInvocation(StringBuilder sb)
             sb.AppendLine(");");
         }
 
+        // Logging
+        sb.Append("                 __proxyInvoker.Logger?.Log(global::NexNet.Logging.NexusLogLevel.Information, __proxyInvoker.Logger.Category, null, $\"Proxy Invoking Method: ");
+        sb.Append(this.Name).Append("(");
+        for (var i = 0; i < Parameters.Length; i++)
+        {
+            if (Parameters[i].IsCancellationToken)
+            {
+                sb.Append(Parameters[i].Name)
+                    .Append(", ");
+            }
+            else
+            {
+                sb.Append(Parameters[i].Name)
+                    .Append(" = ")
+                    .Append("{__proxyInvocationArguments.Item").Append(i + 1)
+                    .Append("}, ");
+            }
+        }
+
+        if (Parameters.Length > 0) 
+            sb.Remove(sb.Length - 2, 2);
+
+        sb.AppendLine(");\");");
         sb.Append("                 ");
 
 
@@ -413,15 +494,15 @@ public void EmitProxyMethodInvocation(StringBuilder sb)
             // If we have a duplex pipe parameter, we need to invoke the method and then return the invocation result.
             sb.Append(this.DuplexPipeParameter == null ? "_ = " : "return ");
 
-            sb.Append("__ProxyInvokeMethodCore(").Append(this.Id).Append(", ");
+            sb.Append("__proxyInvoker.ProxyInvokeMethodCore(").Append(this.Id).Append(", ");
             sb.Append(SerializedParameters > 0 ? "__proxyInvocationArguments, " : "null, ");
 
             // If we have a duplex pipe parameter, we need to pass the duplex pipe invocation flag.
             sb.Append("global::NexNet.Messages.InvocationFlags.").Append(this.DuplexPipeParameter == null ? "None" : "DuplexPipe").AppendLine(");");
         }
         else if (this.IsAsync)
         {
-            sb.Append("return __ProxyInvokeAndWaitForResultCore");
+            sb.Append("return __proxyInvoker.ProxyInvokeAndWaitForResultCore");
             if (this.ReturnType != null)
             {
                 sb.Append("<").Append(this.ReturnType).Append(">");

src/NexNet.Generator/NexusGenerator.Parser.cs

@@ -429,15 +429,15 @@ public MethodParameterMeta(IParameterSymbol symbol, int index)
         {
             // Duplex Pipe is serialized as a byte.
             SerializedType = "global::System.Byte";
-            SerializedValue = $"__ProxyGetDuplexPipeInitialId({Name})";
+            SerializedValue = $"__proxyInvoker.ProxyGetDuplexPipeInitialId({Name})";
         }
         else if (IsDuplexUnmanagedChannel || IsDuplexChannel)
         {
             var returnSymbol = symbol.Type as INamedTypeSymbol;
             ChannelType = SymbolUtilities.GetFullSymbolType(returnSymbol?.TypeArguments[0], false);
             // Duplex Pipe is serialized as a byte.
             SerializedType = "global::System.Byte";
-            SerializedValue = $"__ProxyGetDuplexPipeInitialId({Name}.BasePipe)";
+            SerializedValue = $"__proxyInvoker.ProxyGetDuplexPipeInitialId({Name}.BasePipe)";
         }
         else if(IsCancellationToken)
         {
@@ -574,7 +574,7 @@ public override string ToString()
         {
             sb.Append("void");
         }
-        else if(IsAsync)
+        else if (IsAsync)
         {
             sb.Append("ValueTask");
 
@@ -585,7 +585,6 @@ public override string ToString()
         }
 
         sb.Append(" ");
-
         sb.Append(this.Name).Append("(");
 
         var paramsLength = this.Parameters.Length;
@@ -603,7 +602,7 @@ public override string ToString()
                 }
             }
         }
-        
+
         sb.Append(")");
 
         var stringMethod = sb.ToString();

src/NexNet.props

@@ -1,6 +1,6 @@
 <Project>
   <PropertyGroup>
-    <Version>0.6.0</Version>
+    <Version>0.7.0</Version>
     <Nullable>enable</Nullable>
     <LangVersion>latest</LangVersion>
     <TargetFramework>net8.0</TargetFramework>

src/NexNet/Internals/NexusSession.Receiving.cs

@@ -137,8 +137,8 @@ private async ValueTask<ProcessResult> Process(ReadOnlySequence<byte> sequence)
                             break;
 
                         default:
-                            Logger?.LogTrace($"Received invalid MessageHeader '{_recMessageHeader.Type}'.");
-                            // If we are outside of the acceptable messages, disconnect the connection.
+                            Logger?.LogInfo($"Received invalid MessageHeader '{_recMessageHeader.Type}'.");
+                            // If we are outside the acceptable messages, disconnect the connection.
                             disconnect = DisconnectReason.ProtocolError;
                             break;
                     }
@@ -187,7 +187,7 @@ private async ValueTask<ProcessResult> Process(ReadOnlySequence<byte> sequence)
                             break;
                         default:
                             Logger?.LogTrace($"Received invalid combination of PostHeaderLength ({_recMessageHeader.PostHeaderLength}) and MessageType ({_recMessageHeader.Type}).");
-                            // If we are outside of the acceptable messages, disconnect the connection.
+                            // If we are outside the acceptable messages, disconnect the connection.
                             disconnect = DisconnectReason.ProtocolError;
                             break;
 
@@ -205,7 +205,6 @@ private async ValueTask<ProcessResult> Process(ReadOnlySequence<byte> sequence)
             }
 
             //Logger?.LogTrace($"Read all the {_recMessageHeader.BodyLength} body bytes.");
-
             var bodySlice = sequence.Slice(position, _recMessageHeader.BodyLength);
 
             position += _recMessageHeader.BodyLength;

src/NexNet/Internals/NexusSession.cs

@@ -121,7 +121,7 @@ public NexusSession(in NexusSessionConfigurations<TNexus, TProxy> configurations
             ? new ServerSessionContext<TProxy>(this, _sessionManager!)
             : new ClientSessionContext<TProxy>(this);
 
-        Logger = configurations.Configs.Logger?.CreateLogger($"NexusSession", Id.ToString());
+        Logger = configurations.Configs.Logger?.CreateLogger("NexusSession", Id.ToString());
 
         PipeManager = _cacheManager.PipeManagerCache.Rent(this);
         PipeManager.Setup(this);

src/NexNet/Invocation/IProxyInvoker.cs

@@ -1,15 +1,77 @@
-using NexNet.Internals;
+using System;
+using System.Runtime.CompilerServices;
+using System.Threading;
+using System.Threading.Tasks;
+using NexNet.Internals;
+using NexNet.Logging;
+using NexNet.Messages;
+using NexNet.Pipes;
 
 namespace NexNet.Invocation;
 
 /// <summary>
-/// Interface for invocations on on remote hubs.
+/// Interface for invocations on remote hubs.
 /// </summary>
 public interface IProxyInvoker
 {
+    /// <summary>
+    /// Configures the proxy invoker with the specified parameters.
+    /// </summary>
+    /// <param name="session">The session to be used by the proxy invoker. Can be null.</param>
+    /// <param name="sessionManager">The session manager to be used by the proxy invoker. Can be null.</param>
+    /// <param name="mode">The invocation mode to be used by the proxy invoker.</param>
+    /// <param name="modeArguments">The arguments for the invocation mode. Can be null.</param>
     internal void Configure(
         INexusSession? session,
         SessionManager? sessionManager,
         ProxyInvocationMode mode,
         object? modeArguments);
+
+    /// <summary>
+    /// Logger for the current session.
+    /// </summary>
+    INexusLogger? Logger { get; }
+
+    /// <summary>
+    /// Invokes the specified method on the connected session and waits until the message has been completely sent.
+    /// Will not wait for results on invocations and will instruct the proxy to dismiss any results.
+    /// </summary>
+    /// <param name="methodId">Method ID to invoke.</param>
+    /// <param name="arguments">Optional arguments to pass to the method invocation.</param>
+    /// <param name="flags">Special flags for the invocation of this method.</param>
+    /// <returns>Task which returns when the invocations messages have been issued.</returns>
+    /// <exception cref="ArgumentOutOfRangeException">Thrown if the invocation mode is set in an invalid mode.</exception>
+    ValueTask ProxyInvokeMethodCore(ushort methodId, ITuple? arguments, InvocationFlags flags);
+
+    /// <summary>
+    /// Invokes a method ID on the connection with the optionally passed arguments and optional cancellation token
+    /// and waits the completion of the invocation.
+    /// </summary>
+    /// <param name="methodId">Method ID to invoke.</param>
+    /// <param name="arguments">Optional arguments to pass to the method invocation</param>
+    /// <param name="cancellationToken">Optional cancellation token to allow cancellation of remote invocation.</param>
+    /// <returns>ValueTask which completes upon remote invocation completion.</returns>
+    /// <exception cref="ProxyRemoteInvocationException">Throws this exception if the remote invocation threw an exception.</exception>
+    /// <exception cref="InvalidOperationException">Invocation returned invalid state data upon completion.</exception>
+    ValueTask ProxyInvokeAndWaitForResultCore(ushort methodId, ITuple? arguments, CancellationToken? cancellationToken = null);
+
+    /// <summary>
+    /// Invokes a method ID on the connection with the optionally passed arguments and optional cancellation token,
+    /// waits the completion of the invocation and returns the value of the invocation.
+    /// </summary>
+    /// <typeparam name="TReturn">Expected type to be returned by the remote invocation proxy.</typeparam>
+    /// <param name="methodId">Method ID to invoke.</param>
+    /// <param name="arguments">Optional arguments to pass to the method invocation</param>
+    /// <param name="cancellationToken">Optional cancellation token to allow cancellation of remote invocation.</param>
+    /// <returns>ValueTask with the containing return result which completes upon remote invocation completion.</returns>
+    /// <exception cref="ProxyRemoteInvocationException">Throws this exception if the remote invocation threw an exception.</exception>
+    /// <exception cref="InvalidOperationException">Invocation returned invalid state data upon completion.</exception>
+    ValueTask<TReturn> ProxyInvokeAndWaitForResultCore<TReturn>(ushort methodId, ITuple? arguments, CancellationToken? cancellationToken = null);
+
+    /// <summary>
+    /// Gets the Initial Id of the duplex pipe.
+    /// </summary>
+    /// <param name="pipe">Pipe to retrieve the Id of.</param>
+    /// <returns>Initial id of the pipe.</returns>
+    byte ProxyGetDuplexPipeInitialId(INexusDuplexPipe? pipe);
 }