diff --git a/cs/src/Connections/SshSessionExtensions.cs b/cs/src/Connections/SshSessionExtensions.cs new file mode 100644 index 00000000..4bcb6961 --- /dev/null +++ b/cs/src/Connections/SshSessionExtensions.cs @@ -0,0 +1,17 @@ +using System; +using Microsoft.DevTunnels.Ssh; + +namespace Microsoft.DevTunnels.Connections; + +internal static class SshSessionExtensions +{ + public static string GetShortSessionId(this SshSession session) + { + if (session.SessionId == null || session.SessionId.Length < 16) + { + return string.Empty; + } + + return new Guid(session.SessionId.AsSpan(0, 16)).ToString(); + } +} diff --git a/cs/src/Connections/TunnelClient.cs b/cs/src/Connections/TunnelClient.cs index e8048e5e..5b99a8d9 100644 --- a/cs/src/Connections/TunnelClient.cs +++ b/cs/src/Connections/TunnelClient.cs @@ -140,7 +140,7 @@ public override async Task ConnectAsync( Requires.NotNull(tunnel, nameof(tunnel)); Requires.NotNull(tunnel.Endpoints!, nameof(Tunnel.Endpoints)); - if (this.SshSession != null) + if (this.SshSession?.IsConnected == true) { throw new InvalidOperationException( "Already connected. Use separate instances to connect to multiple tunnels."); @@ -240,6 +240,7 @@ protected async Task StartSshSessionAsync(Stream stream, TunnelConnectionOptions private void OnSshSessionDisconnected(object? sender, EventArgs e) => MaybeStartReconnecting( + (SshSession)sender!, SshDisconnectReason.ConnectionLost, exception: new SshConnectionException("Connection lost.", SshDisconnectReason.ConnectionLost)); diff --git a/cs/src/Connections/TunnelConnection.cs b/cs/src/Connections/TunnelConnection.cs index 41563187..824a2c94 100644 --- a/cs/src/Connections/TunnelConnection.cs +++ b/cs/src/Connections/TunnelConnection.cs @@ -22,7 +22,6 @@ public abstract class TunnelConnection : IAsyncDisposable { private readonly CancellationTokenSource disposeCts = new(); private ConnectionStatus connectionStatus; - private Stopwatch connectionTimer = new(); private Tunnel? tunnel; /// @@ -423,25 +422,6 @@ protected virtual void OnConnectionStatusChanged( ConnectionStatus previousConnectionStatus, ConnectionStatus connectionStatus) { - TimeSpan duration = this.connectionTimer.Elapsed; - this.connectionTimer.Restart(); - - if (Tunnel != null) - { - var statusEvent = new TunnelEvent($"{ConnectionRole}_connection_status"); - statusEvent.Properties = new Dictionary - { - [nameof(ConnectionStatus)] = connectionStatus.ToString(), - [$"Previous{nameof(ConnectionStatus)}"] = previousConnectionStatus.ToString(), - }; - if (previousConnectionStatus != ConnectionStatus.None) - { - statusEvent.Properties[$"{previousConnectionStatus}Duration"] = duration.ToString(); - } - - ManagementClient?.ReportEvent(Tunnel, statusEvent); - } - var handler = ConnectionStatusChanged; if (handler != null) { diff --git a/cs/src/Connections/TunnelRelayConnection.cs b/cs/src/Connections/TunnelRelayConnection.cs index 44e8d604..c71937e3 100644 --- a/cs/src/Connections/TunnelRelayConnection.cs +++ b/cs/src/Connections/TunnelRelayConnection.cs @@ -4,6 +4,7 @@ // using System; +using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Threading; @@ -55,8 +56,10 @@ public abstract class TunnelRelayConnection : TunnelConnection, IRelayClient, IP /// public const int RetryMaxDelayMs = 12_800; + private string? websocketRequestId = null; private TunnelConnectionOptions? connectionOptions; private Task? reconnectTask; + private Stopwatch connectionTimer = new(); /// /// Create a new instance of class. @@ -66,6 +69,12 @@ protected TunnelRelayConnection(ITunnelManagementClient? managementClient, Trace { } + /// + /// Gets an ID that is unique to this instance of , + /// useful for correlating connection events over time. + /// + protected virtual string ConnectionId { get; } = Guid.NewGuid().ToString(); + /// /// Connection protocol used to connect to Relay. /// @@ -170,11 +179,60 @@ protected async Task ConnectTunnelSessionAsync( } } + /// + /// Event fired when the connection status has changed. + /// + protected override void OnConnectionStatusChanged( + ConnectionStatus previousConnectionStatus, + ConnectionStatus connectionStatus) + { + TimeSpan duration = this.connectionTimer.Elapsed; + this.connectionTimer.Restart(); + + if (Tunnel != null && ManagementClient != null) + { + var statusEvent = new TunnelEvent($"{ConnectionRole}_connection_status"); + statusEvent.Properties = new Dictionary + { + [nameof(ConnectionStatus)] = connectionStatus.ToString(), + [$"Previous{nameof(ConnectionStatus)}"] = previousConnectionStatus.ToString(), + }; + + if (previousConnectionStatus != ConnectionStatus.None) + { + statusEvent.Properties[$"{previousConnectionStatus}Duration"] = duration.ToString(); + } + + if (IsClientConnection) + { + // For client sessions, report the SSH session ID property, which is derived from + // the SSH key-exchange such that both host and client have the same ID. + statusEvent.Properties["ClientSessionId"] = SshSession?.GetShortSessionId() ?? string.Empty; + } + else + { + // For host sessions, there is no SSH encryption or key-exchange. + // Just use a locally-generated GUID that is unique to this session. + statusEvent.Properties["HostSessionId"] = ConnectionId; + } + + if (this.websocketRequestId != null) + { + statusEvent.Properties["WebsocketRequestId"] = this.websocketRequestId; + } + + ManagementClient.ReportEvent(Tunnel, statusEvent); + } + + base.OnConnectionStatusChanged(previousConnectionStatus, connectionStatus); + } + /// /// Start reconnecting if connected, not reconnecting already, /// and is . /// protected void MaybeStartReconnecting( + SshSession session, SshDisconnectReason reason, string? message = null, Exception? exception = null) @@ -214,6 +272,10 @@ protected void MaybeStartReconnecting( var reconnectEvent = new TunnelEvent($"{ConnectionRole}_reconnect"); reconnectEvent.Severity = TunnelEvent.Warning; reconnectEvent.Details = exception?.ToString() ?? traceMessage; + reconnectEvent.Properties = new Dictionary + { + ["ClientSessionId"] = session.GetShortSessionId(), + }; ManagementClient?.ReportEvent(Tunnel, reconnectEvent); } @@ -228,6 +290,10 @@ protected void MaybeStartReconnecting( var disconnectEvent = new TunnelEvent($"{ConnectionRole}_disconnect"); disconnectEvent.Severity = TunnelEvent.Warning; disconnectEvent.Details = exception?.ToString() ?? traceMessage; + disconnectEvent.Properties = new Dictionary + { + ["ClientSessionId"] = session.GetShortSessionId(), + }; ManagementClient?.ReportEvent(Tunnel, disconnectEvent); } @@ -271,6 +337,8 @@ protected virtual async Task CreateSessionStreamAsync(CancellationToken cancellation); Trace.TraceEvent(TraceEventType.Verbose, 0, "Connected with subprotocol '{0}'", subprotocol); + this.websocketRequestId = (stream as WebSocketStream)?.RequestId; + if (this.IsClientConnection) { this.OnReportProgress(Progress.OpenedClientConnectionToRelay); @@ -329,7 +397,6 @@ protected virtual async Task CloseSessionAsync( return; } - SshSession = null; UnsubscribeSessionEvents(session); if (!session.IsClosed && session.IsConnected) { @@ -343,6 +410,11 @@ protected virtual async Task CloseSessionAsync( } } + // Set the connection status to disconnected before setting SshSession to null, + // so the session ID can be reported in the disconnect event. + ConnectionStatus = ConnectionStatus.Disconnected; + SshSession = null; + // Closing the SSH session does nothing if the session is in disconnected state, // which may happen for a reconnectable session when the connection drops. // Disposing of the session forces closing and frees up the resources. @@ -355,9 +427,7 @@ protected virtual async Task CloseSessionAsync( protected virtual void OnSshSessionClosed(object? sender, SshSessionClosedEventArgs e) { var session = (SshClientSession)sender!; - UnsubscribeSessionEvents(session); - SshSession = null; - MaybeStartReconnecting(e.Reason, e.Message, e.Exception); + MaybeStartReconnecting(session, e.Reason, e.Message, e.Exception); } /// diff --git a/cs/src/Connections/TunnelRelayTunnelHost.cs b/cs/src/Connections/TunnelRelayTunnelHost.cs index b008f751..288a7293 100644 --- a/cs/src/Connections/TunnelRelayTunnelHost.cs +++ b/cs/src/Connections/TunnelRelayTunnelHost.cs @@ -59,6 +59,9 @@ public TunnelRelayTunnelHost(ITunnelManagementClient managementClient, TraceSour this.hostId = MultiModeTunnelHost.HostId; } + /// + protected override string ConnectionId => this.hostId; + /// /// Get or set synthetic endpoint signature for the endpoint created for the host /// when connecting. @@ -426,6 +429,8 @@ private async Task ConnectAndRunClientSessionAsync(SshStream stream, Cancellatio connectedEvent.Properties = new Dictionary { ["ClientChannelId"] = channelId.ToString(), + ["ClientSessionId"] = session.GetShortSessionId(), + ["HostSessionId"] = ConnectionId, }; ManagementClient?.ReportEvent(Tunnel, connectedEvent); } @@ -456,12 +461,15 @@ private async Task ConnectAndRunClientSessionAsync(SshStream stream, Cancellatio async void OnSshClientReconnected(object? sender, EventArgs e) { + var session = (SshSession)sender!; if (Tunnel != null) { var reconnectedEvent = new TunnelEvent($"host_client_reconnect"); reconnectedEvent.Properties = new Dictionary { ["ClientChannelId"] = channelId.ToString(), + ["ClientSessionId"] = session.GetShortSessionId(), + ["HostSessionId"] = ConnectionId, }; ManagementClient?.ReportEvent(Tunnel, reconnectedEvent); } @@ -473,7 +481,8 @@ await StartForwardingExistingPortsAsync( void OnClientSessionClosed(object? sender, SshSessionClosedEventArgs e) { - TraceSource trace = ((SshSession)sender!).Trace; + var session = (SshSession)sender!; + var trace = session.Trace; string? details = null; string? severity = null; @@ -510,6 +519,8 @@ void OnClientSessionClosed(object? sender, SshSessionClosedEventArgs e) disconnectedEvent.Properties = new Dictionary { ["ClientChannelId"] = channelId.ToString(), + ["ClientSessionId"] = session.GetShortSessionId(), + ["HostSessionId"] = ConnectionId, }; ManagementClient?.ReportEvent(Tunnel, disconnectedEvent); } diff --git a/cs/src/Connections/WebSocketStream.cs b/cs/src/Connections/WebSocketStream.cs index 70b820ac..57a24287 100644 --- a/cs/src/Connections/WebSocketStream.cs +++ b/cs/src/Connections/WebSocketStream.cs @@ -7,6 +7,7 @@ using System.Diagnostics; using System.Globalization; using System.IO; +using System.Linq; using System.Net; using System.Net.WebSockets; using System.Threading; @@ -97,12 +98,46 @@ public string? CloseStatusDescription set => this.closeStatusDescription = value; } + /// + /// Gets the HTTP request ID from the web socket connection, if available. + /// + /// + /// The request ID is returned as a response HTTP header when the websocket connection + /// is established. The value can then be added to client-reported events to support + /// correlation with service events. + /// + public string? RequestId + { + get + { +#if NET8_0_OR_GREATER + var responseHeaders = (this.socket as ClientWebSocket)?.HttpResponseHeaders; + if (responseHeaders?.TryGetValue("VsSaaS-Request-ID", out var requestIdValues) == true) + { + var requestId = requestIdValues.FirstOrDefault(); + if (!string.IsNullOrEmpty(requestId)) + { + return requestId; + } + } +#endif + + return null; + } + } + /// /// Connect to web socket. /// public static async Task ConnectToWebSocketAsync(Uri uri, Action? configure = default, TraceSource? trace = default, CancellationToken cancellation = default) { var socket = new ClientWebSocket(); + +#if NET8_0_OR_GREATER + // Enable access to HTTP response headers. + socket.Options.CollectHttpResponseDetails = true; +#endif + try { configure?.Invoke(socket.Options); @@ -125,11 +160,11 @@ public static async Task ConnectToWebSocketAsync(Uri uri, Actio if (i >= 0) { int j = wse.Message.IndexOf('\'', i + 1); - if (j > i + 1 && + if (j > i + 1 && int.TryParse( - wse.Message.Substring(i + 1, j - i - 1), + wse.Message.Substring(i + 1, j - i - 1), NumberStyles.None, - CultureInfo.InvariantCulture, + CultureInfo.InvariantCulture, out var statusCode) && statusCode != 101) { diff --git a/ts/src/connections/tunnelConnectionSession.ts b/ts/src/connections/tunnelConnectionSession.ts index ecb6721e..363dc220 100644 --- a/ts/src/connections/tunnelConnectionSession.ts +++ b/ts/src/connections/tunnelConnectionSession.ts @@ -19,6 +19,7 @@ import { Progress, SshClientSession, SshDisconnectReason, + SshSession, SshSessionClosedEventArgs, Stream, Trace, @@ -45,6 +46,7 @@ import { RetryingTunnelConnectionEventArgs } from './retryingTunnelConnectionEve import { TunnelRelayStreamFactory } from './tunnelRelayStreamFactory'; import { DefaultTunnelRelayStreamFactory } from './defaultTunnelRelayStreamFactory'; import { IClientConfig } from 'websocket'; +import { v4 as uuidv4 } from 'uuid'; /** * Tunnel connection session. @@ -56,6 +58,9 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun private reconnectPromise?: Promise; private connectionProtocolValue?: string; private disconnectionReason?: SshDisconnectReason; + private connectionStartTime: number = Date.now(); + + private readonly uniqueConnectionId: string = uuidv4(); private readonly refreshingTunnelEmitter = new TrackingEmitter(); @@ -92,6 +97,14 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun this.connectionProtocolValue = value; } + /** + * Gets an ID that is unique to this instance of `TunnelConnectionSession`, + * useful for correlating connection events over time. + */ + protected get connectionId() { + return this.uniqueConnectionId; + } + /** * A value indicating if this is a client tunnel connection (as opposed to host connection). */ @@ -141,21 +154,32 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun severity: TunnelEvent.info, details: undefined, properties: { - 'ConnectionStatus': status.toString(), - 'PreviousConnectionStatus': previousStatus.toString() + ConnectionStatus: status.toString(), + PreviousConnectionStatus: previousStatus.toString() }, }; - - // Add duration property if we had a previous status + if (previousStatus !== ConnectionStatus.None) { - // Note: In C# this uses a duration calculation, but we don't have - // timing information readily available in TypeScript, so we'll skip this for now - // statusEvent.properties[`${previousStatus}Duration`] = duration.toString(); + // Format the duration as a TimeSpan in the form "00:00:00.000" + const duration = Date.now() - this.connectionStartTime; + const formattedDuration = new Date(duration).toISOString().substring(11, 23); + statusEvent.properties![`${previousStatus}Duration`] = formattedDuration; } - + + if (this.isClientConnection) { + // For client sessions, report the SSH session ID property, which is derived from + // the SSH key-exchange such that both host and client have the same ID. + statusEvent.properties!.ClientSessionId = this.getShortSessionId(this.sshSession); + } else { + // For host sessions, there is no SSH encryption or key-exchange. + // Just use a locally-generated GUID that is unique to this session. + statusEvent.properties!.HostSessionId = this.connectionId; + } + this.managementClient.reportEvent(this.tunnel, statusEvent); } + this.connectionStartTime = Date.now(); super.onConnectionStatusChanged(previousStatus, status); } @@ -575,6 +599,9 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun name: `${this.connectionRole}_reconnect`, severity: TunnelEvent.warning, details: error?.toString() ?? message, + properties: { + ClientSessionId: this.getShortSessionId(this.sshSession), + }, }; this.managementClient.reportEvent(this.tunnel, reconnectEvent); } @@ -590,6 +617,9 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun name: `${this.connectionRole}_reconnect_failed`, severity: TunnelEvent.error, details: ex instanceof Error ? ex.toString() : String(ex), + properties: { + ClientSessionId: this.getShortSessionId(this.sshSession), + }, }; this.managementClient.reportEvent(this.tunnel, reconnectFailedEvent); } @@ -607,6 +637,9 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun name: `${this.connectionRole}_disconnect`, severity: TunnelEvent.warning, details: error?.toString() ?? message, + properties: { + ClientSessionId: this.getShortSessionId(this.sshSession), + }, }; this.managementClient.reportEvent(this.tunnel, disconnectEvent); } @@ -769,4 +802,20 @@ export class TunnelConnectionSession extends TunnelConnectionBase implements Tun this.sshSessionDisposables.forEach((d) => d.dispose()); this.sshSessionDisposables = []; } + + /** @internal */ + protected getShortSessionId(session?: SshSession): string { + const b = session?.sessionId; + if (!b || b.length < 16) { + return ''; + } + + // Format as a GUID. This cannot use uuid.stringify() because + // the bytes might not be technically valid for a UUID. + return b.subarray(0, 4).toString('hex') + '-' + + b.subarray(4, 6).toString('hex') + '-' + + b.subarray(6, 8).toString('hex') + '-' + + b.subarray(8, 10).toString('hex') + '-' + + b.subarray(10, 16).toString('hex'); + } } diff --git a/ts/src/connections/tunnelRelayTunnelHost.ts b/ts/src/connections/tunnelRelayTunnelHost.ts index 5031ecd8..04f1fa40 100644 --- a/ts/src/connections/tunnelRelayTunnelHost.ts +++ b/ts/src/connections/tunnelRelayTunnelHost.ts @@ -54,7 +54,6 @@ import { SessionPortKey } from './sessionPortKey'; import { PortRelayConnectRequestMessage } from './messages/portRelayConnectRequestMessage'; import { PortRelayConnectResponseMessage } from './messages/portRelayConnectResponseMessage'; import { v4 as uuidv4 } from 'uuid'; - import { TunnelHost } from './tunnelHost'; import { isNode } from './sshHelpers'; import { TunnelConnectionOptions } from './tunnelConnectionOptions'; @@ -136,6 +135,10 @@ export class TunnelRelayTunnelHost extends TunnelConnectionSession implements Tu this.id = uuidv4() + "-relay"; } + protected override get connectionId() { + return this.hostId; + } + /** * A value indicating whether the port-forwarding service forwards connections to local TCP sockets. * Forwarded connections are not possible if the host is not NodeJS (e.g. browser). @@ -511,9 +514,11 @@ export class TunnelRelayTunnelHost extends TunnelConnectionSession implements Tu if (this.tunnel && this.managementClient) { const connectedEvent: TunnelEvent = { - name: 'host_client_connected', + name: 'host_client_connect', properties: { - 'ClientChannelId': clientChannelId.toString(), + ClientChannelId: clientChannelId.toString(), + ClientSessionId: this.getShortSessionId(session), + HostSessionId: this.connectionId, } }; this.managementClient.reportEvent(this.tunnel, connectedEvent); @@ -619,9 +624,11 @@ export class TunnelRelayTunnelHost extends TunnelConnectionSession implements Tu private onClientSessionReconnecting(session: SshServerSession, clientChannelId: number) { if (this.tunnel && this.managementClient) { const reconnectedEvent: TunnelEvent = { - name: 'host_client_reconnecting', + name: 'host_client_reconnect', properties: { - 'ClientChannelId': clientChannelId.toString(), + ClientChannelId: clientChannelId.toString(), + ClientSessionId: this.getShortSessionId(session), + HostSessionId: this.connectionId, } }; this.managementClient.reportEvent(this.tunnel, reconnectedEvent); @@ -658,11 +665,13 @@ export class TunnelRelayTunnelHost extends TunnelConnectionSession implements Tu if (this.tunnel && this.managementClient) { const disconnectedEvent: TunnelEvent = { timestamp: new Date(), - name: 'host_client_disconnected', + name: 'host_client_disconnect', severity: severity, details: details, properties: { - 'ClientChannelId': clientChannelId.toString(), + ClientChannelId: clientChannelId.toString(), + ClientSessionId: this.getShortSessionId(session), + HostSessionId: this.connectionId, } }; this.managementClient.reportEvent(this.tunnel, disconnectedEvent);