diff --git a/build/dependencies.props b/build/dependencies.props index fb2814ddc5..28f7178f8a 100644 --- a/build/dependencies.props +++ b/build/dependencies.props @@ -49,6 +49,7 @@ 2.1.0-preview1-27579 2.1.0-preview1-27579 2.1.0-preview1-27579 + 2.1.0-preview1-27579 2.0.0 2.6.0-beta2-62211-02 15.3.0 diff --git a/src/Microsoft.AspNetCore.Sockets/ConnectionManager.cs b/src/Microsoft.AspNetCore.Sockets/ConnectionManager.cs index 9baa558045..58536855d8 100644 --- a/src/Microsoft.AspNetCore.Sockets/ConnectionManager.cs +++ b/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(); var applicationToTransport = Channel.CreateUnbounded(); @@ -66,6 +67,7 @@ namespace Microsoft.AspNetCore.Sockets var applicationSide = ChannelConnection.Create(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); } } diff --git a/src/Microsoft.AspNetCore.Sockets/DefaultConnectionContext.cs b/src/Microsoft.AspNetCore.Sockets/DefaultConnectionContext.cs index 990827767b..5c7c853a2d 100644 --- a/src/Microsoft.AspNetCore.Sockets/DefaultConnectionContext.cs +++ b/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 _disposeTcs = new TaskCompletionSource(); + internal ValueStopwatch ConnectionTimer { get; set; } public DefaultConnectionContext(string id, Channel transport, Channel application) { diff --git a/src/Microsoft.AspNetCore.Sockets/Internal/SocketEventSource.cs b/src/Microsoft.AspNetCore.Sockets/Internal/SocketEventSource.cs new file mode 100644 index 0000000000..66a1bb6357 --- /dev/null +++ b/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); + } + } + } + } +} diff --git a/src/Microsoft.AspNetCore.Sockets/Internal/SocketLoggerExtensions.cs b/src/Microsoft.AspNetCore.Sockets/Internal/SocketLoggerExtensions.cs index 82af61fbeb..a167ffd048 100644 --- a/src/Microsoft.AspNetCore.Sockets/Internal/SocketLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Sockets/Internal/SocketLoggerExtensions.cs @@ -21,6 +21,9 @@ namespace Microsoft.AspNetCore.Sockets.Internal private static readonly Action _connectionReset = LoggerMessage.Define(LogLevel.Trace, new EventId(3, nameof(ConnectionReset)), "{time}: ConnectionId {connectionId}: Connection was reset."); + private static readonly Action _connectionTimedOut = + LoggerMessage.Define(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)) diff --git a/src/Microsoft.AspNetCore.Sockets/Microsoft.AspNetCore.Sockets.csproj b/src/Microsoft.AspNetCore.Sockets/Microsoft.AspNetCore.Sockets.csproj index 27dd5e9574..02e2be9632 100644 --- a/src/Microsoft.AspNetCore.Sockets/Microsoft.AspNetCore.Sockets.csproj +++ b/src/Microsoft.AspNetCore.Sockets/Microsoft.AspNetCore.Sockets.csproj @@ -13,6 +13,7 @@ +