Add connection logging for tests

cyanfish · Aug 6, 2023 · eb03248 · eb03248
1 parent a3c2b2b
commit eb03248
Show file tree

Hide file tree

Showing 17 changed files with 213 additions and 79 deletions.
diff --git a/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetHttpContextFactory.cs b/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetHttpContextFactory.cs
@@ -31,7 +31,7 @@ public class AspNetHttpContextFactory : ChannelContextFactory
 {
     private int _port;
 
-    public override ChannelContext Create()
+    public override ChannelContext Create(ITestOutputHelper output = null)
     {
         var builder = WebApplication.CreateBuilder();
         builder.Services.AddGrpc(opts => opts.MaxReceiveMessageSize = int.MaxValue);
@@ -54,12 +54,12 @@ public override ChannelContext Create()
         return new ChannelContext
         {
             Impl = new TestServiceImpl(), // TODO: Match instance
-            Client = CreateClient(),
+            Client = CreateClient(output),
             OnDispose = () => app.StopAsync()
         };
     }
 
-    public override TestService.TestServiceClient CreateClient()
+    public override TestService.TestServiceClient CreateClient(ITestOutputHelper output = null)
     {
         var httpHandler = new HttpClientHandler();
         httpHandler.ServerCertificateCustomValidationCallback =

diff --git a/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetPipeContextFactory.cs b/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetPipeContextFactory.cs
@@ -30,7 +30,7 @@ public class AspNetPipeContextFactory : ChannelContextFactory
 {
     private string _pipe;
 
-    public override ChannelContext Create()
+    public override ChannelContext Create(ITestOutputHelper output = null)
     {
         _pipe = $"pipe/{Guid.NewGuid()}";
         var builder = WebApplication.CreateBuilder();
@@ -48,12 +48,12 @@ public override ChannelContext Create()
         return new ChannelContext
         {
             Impl = new TestServiceImpl(), // TODO: Match instance
-            Client = CreateClient(),
+            Client = CreateClient(output),
             OnDispose = () => app.StopAsync()
         };
     }
 
-    public override TestService.TestServiceClient CreateClient()
+    public override TestService.TestServiceClient CreateClient(ITestOutputHelper output = null)
     {
         var connectionFactory = new NamedPipesConnectionFactory(_pipe);
         var socketsHttpHandler = new SocketsHttpHandler

diff --git a/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetUdsContextFactory.cs b/GrpcDotNetNamedPipes.PerfTests/Helpers/AspNetUdsContextFactory.cs
@@ -31,7 +31,7 @@ public class AspNetUdsContextFactory : ChannelContextFactory
 {
     private string _path;
 
-    public override ChannelContext Create()
+    public override ChannelContext Create(ITestOutputHelper output = null)
     {
         _path = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName());
         var builder = WebApplication.CreateBuilder();
@@ -49,12 +49,12 @@ public override ChannelContext Create()
         return new ChannelContext
         {
             Impl = new TestServiceImpl(), // TODO: Match instance
-            Client = CreateClient(),
+            Client = CreateClient(output),
             OnDispose = () => app.StopAsync()
         };
     }
 
-    public override TestService.TestServiceClient CreateClient()
+    public override TestService.TestServiceClient CreateClient(ITestOutputHelper output = null)
     {
         var udsEndPoint = new UnixDomainSocketEndPoint(_path);
         var connectionFactory = new UnixDomainSocketsConnectionFactory(udsEndPoint);

diff --git a/GrpcDotNetNamedPipes.Tests/GrpcNamedPipeTests.cs b/GrpcDotNetNamedPipes.Tests/GrpcNamedPipeTests.cs
diff --git a/GrpcDotNetNamedPipes.Tests/Helpers/ChannelContextFactory.cs b/GrpcDotNetNamedPipes.Tests/Helpers/ChannelContextFactory.cs
@@ -18,6 +18,6 @@ namespace GrpcDotNetNamedPipes.Tests.Helpers;
 
 public abstract class ChannelContextFactory
 {
-    public abstract ChannelContext Create();
-    public abstract TestService.TestServiceClient CreateClient();
+    public abstract ChannelContext Create(ITestOutputHelper output = null);
+    public abstract TestService.TestServiceClient CreateClient(ITestOutputHelper output = null);
 }
diff --git a/GrpcDotNetNamedPipes.Tests/Helpers/HttpChannelContextFactory.cs b/GrpcDotNetNamedPipes.Tests/Helpers/HttpChannelContextFactory.cs
@@ -25,7 +25,7 @@ public class HttpChannelContextFactory : ChannelContextFactory
     };
     private int _port;
 
-    public override ChannelContext Create()
+    public override ChannelContext Create(ITestOutputHelper output = null)
     {
         var impl = new TestServiceImpl();
         var server = new Server(Options)
@@ -38,12 +38,12 @@ public override ChannelContext Create()
         return new ChannelContext
         {
             Impl = impl,
-            Client = CreateClient(),
+            Client = CreateClient(output),
             OnDispose = () => server.KillAsync()
         };
     }
 
-    public override TestService.TestServiceClient CreateClient()
+    public override TestService.TestServiceClient CreateClient(ITestOutputHelper output = null)
     {
         var channel = new Channel(
             "localhost",

diff --git a/GrpcDotNetNamedPipes.Tests/Helpers/NamedPipeChannelContextFactory.cs b/GrpcDotNetNamedPipes.Tests/Helpers/NamedPipeChannelContextFactory.cs
@@ -21,29 +21,30 @@ public class NamedPipeChannelContextFactory : ChannelContextFactory
     private readonly string _pipeName = $"{Guid.NewGuid().ToString().Replace("-", "")}";
     private const int _connectionTimeout = 100;
 
-    public ChannelContext Create(NamedPipeServerOptions options)
+    public ChannelContext Create(NamedPipeServerOptions options, ITestOutputHelper output)
     {
         var impl = new TestServiceImpl();
-        var server = new NamedPipeServer(_pipeName, options);
+        var server = new NamedPipeServer(_pipeName, options, output != null ? output.WriteLine : null);
         TestService.BindService(server.ServiceBinder, impl);
         server.Start();
         return new ChannelContext
         {
             Impl = impl,
-            Client = CreateClient(),
+            Client = CreateClient(output),
             OnDispose = () => server.Kill()
         };
     }
 
-    public override ChannelContext Create()
+    public override ChannelContext Create(ITestOutputHelper output = null)
     {
-        return Create(new NamedPipeServerOptions());
+        return Create(new NamedPipeServerOptions(), output);
     }
 
-    public override TestService.TestServiceClient CreateClient()
+    public override TestService.TestServiceClient CreateClient(ITestOutputHelper output = null)
     {
         var channel = new NamedPipeChannel(".", _pipeName,
-            new NamedPipeChannelOptions { ConnectionTimeout = _connectionTimeout });
+            new NamedPipeChannelOptions { ConnectionTimeout = _connectionTimeout },
+            output != null ? output.WriteLine : null);
         channel.PipeCallback = PipeCallback;
         return new TestService.TestServiceClient(channel);
     }

diff --git a/GrpcDotNetNamedPipes/Internal/ClientConnectionContext.cs b/GrpcDotNetNamedPipes/Internal/ClientConnectionContext.cs
@@ -24,6 +24,7 @@ internal class ClientConnectionContext : TransportMessageHandler, IDisposable
     private readonly PayloadQueue _payloadQueue;
     private readonly Deadline _deadline;
     private readonly int _connectionTimeout;
+    private readonly ConnectionLogger _logger;
 
     private readonly TaskCompletionSource<Metadata> _responseHeadersTcs =
         new(TaskCreationOptions.RunContinuationsAsynchronously);
@@ -34,15 +35,16 @@ internal class ClientConnectionContext : TransportMessageHandler, IDisposable
     private Status _status;
 
     public ClientConnectionContext(NamedPipeClientStream pipeStream, CallOptions callOptions, bool isServerUnary,
-        int connectionTimeout)
+        int connectionTimeout, ConnectionLogger logger)
     {
         _pipeStream = pipeStream;
         _callOptions = callOptions;
         _isServerUnary = isServerUnary;
-        Transport = new NamedPipeTransport(pipeStream);
+        Transport = new NamedPipeTransport(pipeStream, logger);
         _payloadQueue = new PayloadQueue();
         _deadline = new Deadline(callOptions.Deadline);
         _connectionTimeout = connectionTimeout;
+        _logger = logger;
     }
 
     public NamedPipeTransport Transport { get; }

diff --git a/GrpcDotNetNamedPipes/Internal/Helpers/ConnectionLogger.cs b/GrpcDotNetNamedPipes/Internal/Helpers/ConnectionLogger.cs
@@ -0,0 +1,45 @@
+/*
+ * Copyright 2020 Google LLC
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+namespace GrpcDotNetNamedPipes.Internal.Helpers;
+
+internal class ConnectionLogger
+{
+    private static int _lastId;
+
+    private static int NextId() => Interlocked.Increment(ref _lastId);
+    public static ConnectionLogger Client(Action<string> log) => new(log, "CLIENT", log != null ? NextId() : 0);
+    public static ConnectionLogger Server(Action<string> log) => new(log, "SERVER", 0);
+
+    private readonly Action<string> _log;
+    private readonly string _type;
+
+    private ConnectionLogger(Action<string> log, string type, int id)
+    {
+        _log = log;
+        _type = type;
+        ConnectionId = id;
+    }
+
+    public int ConnectionId { get; set; }
+
+    public void Log(string message)
+    {
+        if (_log == null) return;
+        var id = ConnectionId > 0 ? ConnectionId.ToString() : "?";
+        _log($"[{_type}][{id}] {message}");
+    }
+}
diff --git a/GrpcDotNetNamedPipes/Internal/PipeReader.cs b/GrpcDotNetNamedPipes/Internal/PipeReader.cs
@@ -20,18 +20,20 @@ internal class PipeReader
 {
     private readonly PipeStream _pipeStream;
     private readonly TransportMessageHandler _messageHandler;
+    private readonly ConnectionLogger _logger;
     private readonly Action _onDisconnected;
     private readonly Action<Exception> _onError;
     private readonly NamedPipeTransport _transport;
 
-    public PipeReader(PipeStream pipeStream, TransportMessageHandler messageHandler, Action onDisconnected,
-        Action<Exception> onError = null)
+    public PipeReader(PipeStream pipeStream, TransportMessageHandler messageHandler, ConnectionLogger logger,
+        Action onDisconnected, Action<Exception> onError = null)
     {
         _pipeStream = pipeStream;
         _messageHandler = messageHandler;
+        _logger = logger;
         _onDisconnected = onDisconnected;
         _onError = onError;
-        _transport = new NamedPipeTransport(_pipeStream);
+        _transport = new NamedPipeTransport(_pipeStream, logger);
     }
 
     public async Task ReadLoop()
@@ -41,13 +43,17 @@ public async Task ReadLoop()
             while (_pipeStream.IsConnected &&
                    await _transport.Read(_messageHandler).ConfigureAwait(false))
             {
+                await _transport.Read(_messageHandler).ConfigureAwait(false);
             }
+            _logger.Log("Pipe disconnected");
         }
         catch (EndOfPipeException)
         {
+            _logger.Log("End of pipe");
         }
         catch (Exception error)
         {
+            _logger.Log("Pipe read error");
             _onError?.Invoke(error);
         }
         finally

diff --git a/GrpcDotNetNamedPipes/Internal/Protocol/NamedPipeTransport.cs b/GrpcDotNetNamedPipes/Internal/Protocol/NamedPipeTransport.cs
@@ -25,11 +25,13 @@ internal class NamedPipeTransport
 
     private readonly byte[] _messageBuffer = new byte[MessageBufferSize];
     private readonly PipeStream _pipeStream;
+    private readonly ConnectionLogger _logger;
     private readonly WriteTransactionQueue _txQueue;
 
-    public NamedPipeTransport(PipeStream pipeStream)
+    public NamedPipeTransport(PipeStream pipeStream, ConnectionLogger logger)
     {
         _pipeStream = pipeStream;
+        _logger = logger;
         _txQueue = new WriteTransactionQueue(pipeStream);
     }
 
@@ -99,14 +101,18 @@ public async Task<bool> Read(TransportMessageHandler messageHandler)
             switch (message.DataCase)
             {
                 case TransportMessage.DataOneofCase.RequestInit:
+                    _logger.ConnectionId = message.RequestInit.ConnectionId;
+                    _logger.Log($"Received <RequestInit> for '{message.RequestInit.MethodFullName}'");
                     messageHandler.HandleRequestInit(message.RequestInit.MethodFullName,
                         message.RequestInit.Deadline?.ToDateTime());
                     break;
                 case TransportMessage.DataOneofCase.Headers:
+                    _logger.Log("Received <Headers>");
                     var headerMetadata = ConstructMetadata(message.Headers.Metadata);
                     messageHandler.HandleHeaders(headerMetadata);
                     break;
                 case TransportMessage.DataOneofCase.PayloadInfo:
+                    _logger.Log($"Received <PayloadInfo> with {message.PayloadInfo.Size} bytes");
                     var payload = new byte[message.PayloadInfo.Size];
                     if (message.PayloadInfo.InSamePacket)
                     {
@@ -123,15 +129,18 @@ public async Task<bool> Read(TransportMessageHandler messageHandler)
                     switch (message.RequestControl)
                     {
                         case RequestControl.Cancel:
+                            _logger.Log("Received <Cancel>");
                             messageHandler.HandleCancel();
                             break;
                         case RequestControl.StreamEnd:
+                            _logger.Log("Received <StreamEnd>");
                             messageHandler.HandleStreamEnd();
                             break;
                     }
 
                     break;
                 case TransportMessage.DataOneofCase.Trailers:
+                    _logger.Log($"Received <Trailers> with status '{message.Trailers.StatusCode}'");
                     var trailerMetadata = ConstructMetadata(message.Trailers.Metadata);
                     var status = new Status((StatusCode) message.Trailers.StatusCode,
                         message.Trailers.StatusDetail);
@@ -164,6 +173,6 @@ private static Metadata ConstructMetadata(RepeatedField<MetadataEntry> entries)
 
     public WriteTransaction Write()
     {
-        return new WriteTransaction(_txQueue);
+        return new WriteTransaction(_txQueue, _logger);
     }
 }