Adding EventSource/EventCounters to Sockets (#1083)

build/dependencies.props

@@ -49,6 +49,7 @@
     <MicrosoftExtensionsObjectMethodExecutorSourcesPackageVersion>2.1.0-preview1-27579</MicrosoftExtensionsObjectMethodExecutorSourcesPackageVersion>
     <MicrosoftExtensionsOptionsPackageVersion>2.1.0-preview1-27579</MicrosoftExtensionsOptionsPackageVersion>
     <MicrosoftExtensionsSecurityHelperSourcesPackageVersion>2.1.0-preview1-27579</MicrosoftExtensionsSecurityHelperSourcesPackageVersion>
+    <MicrosoftExtensionsValueStopwatchSourcesPackageVersion>2.1.0-preview1-27579</MicrosoftExtensionsValueStopwatchSourcesPackageVersion>
     <MicrosoftNETCoreApp20PackageVersion>2.0.0</MicrosoftNETCoreApp20PackageVersion>
     <MicrosoftNETCoreCompilersPackageVersion>2.6.0-beta2-62211-02</MicrosoftNETCoreCompilersPackageVersion>
     <MicrosoftNETTestSdkPackageVersion>15.3.0</MicrosoftNETTestSdkPackageVersion>

src/Microsoft.AspNetCore.Sockets/ConnectionManager.cs

@@ -58,6 +58,7 @@ namespace Microsoft.AspNetCore.Sockets
             var id = MakeNewConnectionId();
 
             _logger.CreatedNewConnection(id);
+            var connectionTimer = SocketEventSource.Log.ConnectionStart(id);
 
             var transportToApplication = Channel.CreateUnbounded<byte[]>();
             var applicationToTransport = Channel.CreateUnbounded<byte[]>();
@@ -66,6 +67,7 @@ namespace Microsoft.AspNetCore.Sockets
             var applicationSide = ChannelConnection.Create<byte[]>(transportToApplication, applicationToTransport);
 
             var connection = new DefaultConnectionContext(id, applicationSide, transportSide);
+            connection.ConnectionTimer = connectionTimer;
 
             _connections.TryAdd(id, connection);
             return connection;
@@ -73,9 +75,10 @@ namespace Microsoft.AspNetCore.Sockets
 
         public void RemoveConnection(string id)
         {
-            if (_connections.TryRemove(id, out _))
+            if (_connections.TryRemove(id, out var connection))
             {
                 // Remove the connection completely
+                SocketEventSource.Log.ConnectionStop(id, connection.ConnectionTimer);
                 _logger.RemovedConnection(id);
             }
         }
@@ -135,6 +138,8 @@ namespace Microsoft.AspNetCore.Sockets
                     // Once the decision has been made to dispose we don't check the status again
                     if (status == DefaultConnectionContext.ConnectionStatus.Inactive && (DateTimeOffset.UtcNow - lastSeenUtc).TotalSeconds > 5)
                     {
+                        _logger.ConnectionTimedOut(c.Value.ConnectionId);
+                        SocketEventSource.Log.ConnectionTimedOut(c.Value.ConnectionId);
                         var ignore = DisposeAndRemoveAsync(c.Value);
                     }
                 }

src/Microsoft.AspNetCore.Sockets/DefaultConnectionContext.cs

@@ -9,6 +9,7 @@ using System.Threading.Tasks;
 using System.Threading.Channels;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Sockets.Features;
+using Microsoft.Extensions.Internal;
 
 namespace Microsoft.AspNetCore.Sockets
 {
@@ -22,6 +23,7 @@ namespace Microsoft.AspNetCore.Sockets
         // This tcs exists so that multiple calls to DisposeAsync all wait asynchronously
         // on the same task
         private TaskCompletionSource<object> _disposeTcs = new TaskCompletionSource<object>();
+        internal ValueStopwatch ConnectionTimer { get; set; }
 
         public DefaultConnectionContext(string id, Channel<byte[]> transport, Channel<byte[]> application)
         {

src/Microsoft.AspNetCore.Sockets/Internal/SocketEventSource.cs

@@ -0,0 +1,78 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System.Diagnostics.Tracing;
+using Microsoft.Extensions.Internal;
+
+namespace Microsoft.AspNetCore.Sockets.Internal
+{
+    [EventSource(Name = "Microsoft-AspNetCore-Sockets")]
+    internal class SocketEventSource : EventSource
+    {
+        public static readonly SocketEventSource Log = new SocketEventSource();
+
+        private readonly EventCounter _connectionsStarted;
+        private readonly EventCounter _connectionsStopped;
+        private readonly EventCounter _connectionsTimedOut;
+        private readonly EventCounter _connectionDuration;
+
+        private SocketEventSource()
+        {
+            _connectionsStarted = new EventCounter("ConnectionsStarted", this);
+            _connectionsStopped = new EventCounter("ConnectionsStopped", this);
+            _connectionsTimedOut = new EventCounter("ConnectionsTimedOut", this);
+            _connectionDuration = new EventCounter("ConnectionDuration", this);
+        }
+
+        // This has to go through NonEvent because only Primitive types are allowed
+        // in function parameters for Events
+        [NonEvent]
+        public void ConnectionStop(string connectionId, ValueStopwatch timer)
+        {
+            if (IsEnabled())
+            {
+                var duration = timer.IsActive ? timer.GetElapsedTime().TotalMilliseconds : 0.0;
+                _connectionDuration.WriteMetric((float)duration);
+                _connectionsStopped.WriteMetric(1.0f);
+
+                if (IsEnabled(EventLevel.Informational, EventKeywords.None))
+                {
+                    ConnectionStop(connectionId);
+                }
+            }
+        }
+
+        [Event(eventId: 1, Level = EventLevel.Informational, Message = "Started connection '{0}'.")]
+        public ValueStopwatch ConnectionStart(string connectionId)
+        {
+            if (IsEnabled())
+            {
+                _connectionsStarted.WriteMetric(1.0f);
+
+                if (IsEnabled(EventLevel.Informational, EventKeywords.None))
+                {
+                    WriteEvent(1, connectionId);
+                    return ValueStopwatch.StartNew();
+                }
+            }
+            return default;
+        }
+
+        [Event(eventId: 2, Level = EventLevel.Informational, Message = "Stopped connection '{0}'.")]
+        private void ConnectionStop(string connectionId) => WriteEvent(2, connectionId);
+
+        [Event(eventId: 3, Level = EventLevel.Informational, Message = "Connection '{0}' timed out.")]
+        public void ConnectionTimedOut(string connectionId)
+        {
+            if (IsEnabled())
+            {
+                _connectionsTimedOut.WriteMetric(1.0f);
+
+                if (IsEnabled(EventLevel.Informational, EventKeywords.None))
+                {
+                    WriteEvent(3, connectionId);
+                }
+            }
+        }
+    }
+}

src/Microsoft.AspNetCore.Sockets/Internal/SocketLoggerExtensions.cs

@@ -21,6 +21,9 @@ namespace Microsoft.AspNetCore.Sockets.Internal
         private static readonly Action<ILogger, DateTime, string, Exception> _connectionReset =
             LoggerMessage.Define<DateTime, string>(LogLevel.Trace, new EventId(3, nameof(ConnectionReset)), "{time}: ConnectionId {connectionId}: Connection was reset.");
 
+        private static readonly Action<ILogger, DateTime, string, Exception> _connectionTimedOut =
+            LoggerMessage.Define<DateTime, string>(LogLevel.Trace, new EventId(4, nameof(ConnectionTimedOut)), "{time}: ConnectionId {connectionId}: Connection timed out.");
+
         public static void CreatedNewConnection(this ILogger logger, string connectionId)
         {
             if (logger.IsEnabled(LogLevel.Debug))
@@ -45,6 +48,14 @@ namespace Microsoft.AspNetCore.Sockets.Internal
             }
         }
 
+        public static void ConnectionTimedOut(this ILogger logger, string connectionId)
+        {
+            if (logger.IsEnabled(LogLevel.Trace))
+            {
+                _connectionTimedOut(logger, DateTime.Now, connectionId, null);
+            }
+        }
+
         public static void ConnectionReset(this ILogger logger, string connectionId, Exception exception)
         {
             if (logger.IsEnabled(LogLevel.Trace))

src/Microsoft.AspNetCore.Sockets/Microsoft.AspNetCore.Sockets.csproj

@@ -13,6 +13,7 @@
     <PackageReference Include="Microsoft.AspNetCore.Hosting.Abstractions" Version="$(MicrosoftAspNetCoreHostingAbstractionsPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="$(MicrosoftExtensionsLoggingAbstractionsPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="$(MicrosoftExtensionsDependencyInjectionAbstractionsPackageVersion)" />
+    <PackageReference Include="Microsoft.Extensions.ValueStopwatch.Sources" Version="$(MicrosoftExtensionsValueStopwatchSourcesPackageVersion)" PrivateAssets="All" />
     <PackageReference Include="System.Threading.Channels" Version="$(SystemThreadingChannelsPackageVersion)" />
   </ItemGroup>