diff --git a/GVFS/GVFS.Common/NativeMethods.cs b/GVFS/GVFS.Common/NativeMethods.cs index 01282679e..1fae6876d 100644 --- a/GVFS/GVFS.Common/NativeMethods.cs +++ b/GVFS/GVFS.Common/NativeMethods.cs @@ -247,6 +247,19 @@ private static extern bool DeviceIoControl( [DllImport("kernel32.dll")] private static extern ulong GetTickCount64(); + [DllImport("kernel32.dll")] + private static extern int WTSGetActiveConsoleSessionId(); + + /// + /// Returns the session ID of the physical console session, or -1 if + /// no interactive session is active (e.g. at boot before logon). + /// + public static int GetActiveConsoleSessionId() + { + int sessionId = WTSGetActiveConsoleSessionId(); + return sessionId == unchecked((int)0xFFFFFFFF) ? -1 : sessionId; + } + [DllImport("kernel32.dll", SetLastError = true)] private static extern bool SetFileTime( SafeFileHandle hFile, diff --git a/GVFS/GVFS.Common/Tracing/JsonTracer.cs b/GVFS/GVFS.Common/Tracing/JsonTracer.cs index c494bd012..bdc7e6c2d 100644 --- a/GVFS/GVFS.Common/Tracing/JsonTracer.cs +++ b/GVFS/GVFS.Common/Tracing/JsonTracer.cs @@ -22,6 +22,21 @@ public class JsonTracer : ITracer, IEventListenerEventSink private readonly EventLevel startStopLevel; private readonly Keywords startStopKeywords; + // Deferred telemetry pipe: when the daemon listener can't be created + // at construction time (e.g. SYSTEM account can't read user's global + // git config, or telemetry collector not yet installed), buffer + // telemetry messages and replay them when TryAttachTelemetryPipe() + // succeeds. A retry timer periodically re-checks the config. + private string deferredProviderName; + private string deferredEnlistmentId; + private string deferredMountId; + private string deferredGitBinRoot; + private ConcurrentQueue deferredMessages; + private readonly Lock deferredLock = new Lock(); + private Timer deferredRetryTimer; + private int deferredRetryCount; + private const int MaxDeferredMessages = 1000; + private bool isDisposed = false; private bool stopped = false; @@ -59,6 +74,60 @@ public JsonTracer(string providerName, Guid providerActivityId, string activityN { this.listeners.Add(daemonListener); } + else + { + // Pipe config not available (e.g. running as SYSTEM without + // access to user's global git config, or telemetry collector + // not yet installed). Defer listener creation — buffer + // telemetry messages and periodically retry until the config + // becomes available. + this.deferredProviderName = providerName; + this.deferredEnlistmentId = enlistmentId; + this.deferredMountId = mountId; + this.deferredGitBinRoot = gitBinRoot; + this.deferredMessages = new ConcurrentQueue(); + this.StartDeferredRetryTimer(); + } + } + } + + /// + /// Creates a JsonTracer in deferred telemetry mode for testing. + /// No timer is started — call TryAttachTelemetryPipe manually. + /// + internal static JsonTracer CreateDeferredForTesting(string providerName, string activityName) + { + JsonTracer tracer = new JsonTracer(null, Guid.Empty, activityName, EventLevel.Informational, Keywords.Telemetry); + tracer.deferredProviderName = providerName; + tracer.deferredMessages = new ConcurrentQueue(); + return tracer; + } + + /// + /// Attaches the given listener as if TelemetryDaemonEventListener + /// had been created, replaying buffered messages. For testing only. + /// + internal bool TryAttachTestListener(EventListener listener) + { + lock (this.deferredLock) + { + if (this.deferredMessages == null) + { + return false; + } + + this.listeners.Add(listener); + + ConcurrentQueue queue = this.deferredMessages; + this.deferredMessages = null; + this.StopDeferredRetryTimer(); + + while (queue.TryDequeue(out TraceEventMessage message)) + { + listener.RecordMessage(message); + } + + return true; } } @@ -132,6 +201,11 @@ public void Dispose() this.Stop(null); + lock (this.deferredLock) + { + this.StopDeferredRetryTimer(); + } + // If we have no parent, then we are the root tracer and should dispose our eventsource. if (this.parentActivityId == Guid.Empty) { @@ -394,6 +468,18 @@ private void WriteEvent(string eventName, EventLevel level, Keywords keywords, E { listener.RecordMessage(message); } + + // Buffer telemetry messages for deferred pipe attachment. + // Non-telemetry messages (log file, etc.) are not buffered + // since they only matter for the daemon listener. + if (keywords == Keywords.Telemetry) + { + ConcurrentQueue queue = this.deferredMessages; + if (queue != null && queue.Count < MaxDeferredMessages) + { + queue.Enqueue(message); + } + } } private void LogMessageToNonFailedListeners(TraceEventMessage message) @@ -404,5 +490,127 @@ private void LogMessageToNonFailedListeners(TraceEventMessage message) listener.RecordMessage(message); } } + + /// + /// Attempts to create and attach a TelemetryDaemonEventListener using + /// the specified git binary path to read config. Call this when a user + /// session becomes available (e.g. on SessionLogon) so the user's global + /// git config can be read. Replays any buffered pre-logon messages. + /// Safe to call multiple times — no-ops after first successful attach. + /// + /// true if the listener was attached (now or previously). + public bool TryAttachTelemetryPipe(string gitBinRoot) + { + lock (this.deferredLock) + { + // Already attached or not in deferred mode + if (this.deferredMessages == null) + { + return this.listeners.Any(l => l is TelemetryDaemonEventListener); + } + + if (string.IsNullOrEmpty(gitBinRoot)) + { + return false; + } + + TelemetryDaemonEventListener daemonListener; + try + { + daemonListener = TelemetryDaemonEventListener.CreateIfEnabled( + gitBinRoot, + this.deferredProviderName, + this.deferredEnlistmentId, + this.deferredMountId, + this); + } + catch (Exception) + { + return false; + } + + if (daemonListener == null) + { + return false; + } + + this.listeners.Add(daemonListener); + + // Replay buffered messages then stop buffering + ConcurrentQueue queue = this.deferredMessages; + this.deferredMessages = null; + this.StopDeferredRetryTimer(); + + while (queue.TryDequeue(out TraceEventMessage message)) + { + daemonListener.RecordMessage(message); + } + + return true; + } + } + + /// + /// Starts a timer that periodically retries TryAttachTelemetryPipe + /// using the stashed gitBinRoot from construction time. Uses + /// exponential backoff: 10s, 30s, 1m, 5m, then 5m steady state. + /// The timer is stopped when attach succeeds or the tracer is disposed. + /// + private void StartDeferredRetryTimer() + { + lock (this.deferredLock) + { + if (this.deferredRetryTimer != null) + { + return; + } + + this.deferredRetryCount = 0; + this.deferredRetryTimer = new Timer( + this.OnDeferredRetryTimer, + null, + GetRetryInterval(0), + Timeout.Infinite); + } + } + + private void StopDeferredRetryTimer() + { + // Must be called while holding deferredLock + if (this.deferredRetryTimer != null) + { + this.deferredRetryTimer.Dispose(); + this.deferredRetryTimer = null; + } + } + + private void OnDeferredRetryTimer(object state) + { + bool attached = this.TryAttachTelemetryPipe(this.deferredGitBinRoot); + if (!attached) + { + lock (this.deferredLock) + { + if (this.deferredRetryTimer != null && !this.isDisposed) + { + this.deferredRetryCount++; + this.deferredRetryTimer.Change( + GetRetryInterval(this.deferredRetryCount), + Timeout.Infinite); + } + } + } + } + + internal static int GetRetryInterval(int retryCount) + { + return retryCount switch + { + 0 => 10_000, // 10 seconds + 1 => 30_000, // 30 seconds + 2 => 60_000, // 1 minute + _ => 300_000, // 5 minutes + }; + } } } diff --git a/GVFS/GVFS.Service/GVFSService.Windows.cs b/GVFS/GVFS.Service/GVFSService.Windows.cs index 72a313a9d..89db2c32c 100644 --- a/GVFS/GVFS.Service/GVFSService.Windows.cs +++ b/GVFS/GVFS.Service/GVFSService.Windows.cs @@ -8,6 +8,7 @@ using System.IO; using System.Linq; using System.Security.AccessControl; +using System.Security.Principal; using System.ServiceProcess; using System.Threading; @@ -75,6 +76,17 @@ public void Run() { this.CheckEnableGitStatusCacheTokenFile(); + // If a user is already logged in when the service starts + // (e.g. service restart, installer upgrade during active + // session), attach the telemetry pipe now. At boot, + // no session exists yet and this is a harmless no-op; + // OnSessionChange will attach later. + int activeSession = NativeMethods.GetActiveConsoleSessionId(); + if (activeSession > 0) + { + this.TryAttachTelemetryPipeForSession(activeSession); + } + using (ITracer activity = this.tracer.StartActivity("EnsurePrjFltHealthy", EventLevel.Informational)) { // Make a best-effort to enable PrjFlt. Continue even if it fails. @@ -147,6 +159,11 @@ protected override void OnSessionChange(SessionChangeDescription changeDescripti { this.tracer.RelatedInfo("SessionLogon detected, sessionId: {0}", changeDescription.SessionId); + // Attempt to attach the telemetry pipe now that a user + // session is available. Buffered pre-logon events are + // replayed. No-ops if already attached. + this.TryAttachTelemetryPipeForSession(changeDescription.SessionId); + using (ITracer activity = this.tracer.StartActivity("LogonAutomount", EventLevel.Informational)) { this.repoRegistry.AutoMountRepos( @@ -391,6 +408,57 @@ private void CreateAndConfigureLogDirectory(string path) } } + /// + /// Impersonates the logged-on user to read their global git config + /// (which contains gvfs.telemetry-pipe) and attach the telemetry + /// daemon listener. Any events buffered before logon are replayed. + /// RunImpersonated only changes the thread token — it does not load + /// the user profile. We set HOME explicitly so git can find .gitconfig. + /// + private void TryAttachTelemetryPipeForSession(int sessionId) + { + try + { + using (CurrentUser user = new CurrentUser(this.tracer, sessionId)) + { + if (user.Identity == null) + { + this.tracer.RelatedWarning("TryAttachTelemetryPipe: Could not get user identity for session {0}", sessionId); + return; + } + + string gitBinRoot = GVFSPlatform.Instance.GitInstallation.GetInstalledGitBinPath(); + + string userProfile = null; + WindowsIdentity.RunImpersonated(user.Identity.AccessToken, () => + { + userProfile = Environment.GetFolderPath(Environment.SpecialFolder.UserProfile); + }); + + if (string.IsNullOrEmpty(userProfile)) + { + this.tracer.RelatedWarning("TryAttachTelemetryPipe: Could not resolve user profile for session {0}", sessionId); + return; + } + + string oldHome = Environment.GetEnvironmentVariable("HOME"); + try + { + Environment.SetEnvironmentVariable("HOME", userProfile); + this.tracer.TryAttachTelemetryPipe(gitBinRoot); + } + finally + { + Environment.SetEnvironmentVariable("HOME", oldHome); + } + } + } + catch (Exception e) + { + this.tracer.RelatedWarning("TryAttachTelemetryPipe failed: {0}", e.Message); + } + } + private DirectorySecurity GetServiceDirectorySecurity(string serviceDataRootPath) { DirectorySecurity serviceDataRootSecurity; diff --git a/GVFS/GVFS.UnitTests/Common/JsonTracerDeferredTests.cs b/GVFS/GVFS.UnitTests/Common/JsonTracerDeferredTests.cs new file mode 100644 index 000000000..d7fadfc12 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/JsonTracerDeferredTests.cs @@ -0,0 +1,137 @@ +using GVFS.Common.Tracing; +using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common.Tracing; +using NUnit.Framework; + +namespace GVFS.UnitTests.Common +{ + [TestFixture] + public class JsonTracerDeferredTests + { + [TestCase] + public void DeferredMode_BuffersTelemetryMessages() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "BufferTest")) + using (MockListener replayListener = new MockListener(EventLevel.Verbose, Keywords.Telemetry)) + { + tracer.RelatedEvent(EventLevel.Informational, "Event1", metadata: null, keyword: Keywords.Telemetry); + tracer.RelatedEvent(EventLevel.Informational, "Event2", metadata: null, keyword: Keywords.Telemetry); + + bool attached = tracer.TryAttachTestListener(replayListener); + attached.ShouldBeTrue(); + + replayListener.EventNamesRead.Count.ShouldEqual(2); + replayListener.EventNamesRead.ShouldContain(name => name.Equals("Event1")); + replayListener.EventNamesRead.ShouldContain(name => name.Equals("Event2")); + } + } + + [TestCase] + public void DeferredMode_DoesNotBufferNonTelemetryMessages() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "NonTelemetryTest")) + using (MockListener replayListener = new MockListener(EventLevel.Verbose, Keywords.Any)) + { + tracer.RelatedEvent(EventLevel.Informational, "TelemetryEvent", metadata: null, keyword: Keywords.Telemetry); + tracer.RelatedEvent(EventLevel.Informational, "NonTelemetryEvent", metadata: null, keyword: Keywords.Network); + tracer.RelatedEvent(EventLevel.Informational, "PlainEvent", metadata: null); + + bool attached = tracer.TryAttachTestListener(replayListener); + attached.ShouldBeTrue(); + + // Only the telemetry event should have been buffered and replayed + replayListener.EventNamesRead.Count.ShouldEqual(1); + replayListener.EventNamesRead.ShouldContain(name => name.Equals("TelemetryEvent")); + } + } + + [TestCase] + public void DeferredMode_CapsBufferAtMaxMessages() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "CapTest")) + using (MockListener replayListener = new MockListener(EventLevel.Verbose, Keywords.Telemetry)) + { + // Emit 1050 telemetry events — only 1000 should be buffered + for (int i = 0; i < 1050; i++) + { + tracer.RelatedEvent(EventLevel.Informational, $"Event{i}", metadata: null, keyword: Keywords.Telemetry); + } + + bool attached = tracer.TryAttachTestListener(replayListener); + attached.ShouldBeTrue(); + + replayListener.EventNamesRead.Count.ShouldEqual(1000); + replayListener.EventNamesRead[0].ShouldEqual("Event0"); + replayListener.EventNamesRead[999].ShouldEqual("Event999"); + } + } + + [TestCase] + public void TryAttachTestListener_ReturnsFalseWhenNotDeferred() + { + using (JsonTracer tracer = new JsonTracer("TestProvider", "NotDeferredTest", disableTelemetry: true)) + using (MockListener listener = new MockListener(EventLevel.Verbose, Keywords.Any)) + { + // Tracer was not created in deferred mode + bool attached = tracer.TryAttachTestListener(listener); + attached.ShouldBeFalse(); + } + } + + [TestCase] + public void TryAttachTestListener_SecondAttachReturnsFalse() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "DoubleAttachTest")) + using (MockListener listener1 = new MockListener(EventLevel.Verbose, Keywords.Telemetry)) + using (MockListener listener2 = new MockListener(EventLevel.Verbose, Keywords.Telemetry)) + { + tracer.TryAttachTestListener(listener1).ShouldBeTrue(); + + // Second attach should fail — no longer in deferred mode + tracer.TryAttachTestListener(listener2).ShouldBeFalse(); + } + } + + [TestCase] + public void TryAttachTelemetryPipe_ReturnsFalseWithNullGitBinRoot() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "NullGitBinTest")) + { + bool attached = tracer.TryAttachTelemetryPipe(null); + attached.ShouldBeFalse(); + + attached = tracer.TryAttachTelemetryPipe(string.Empty); + attached.ShouldBeFalse(); + } + } + + [TestCase(0, 10_000)] + [TestCase(1, 30_000)] + [TestCase(2, 60_000)] + [TestCase(3, 300_000)] + [TestCase(4, 300_000)] + [TestCase(100, 300_000)] + public void GetRetryInterval_ReturnsExpectedValues(int retryCount, int expectedMs) + { + JsonTracer.GetRetryInterval(retryCount).ShouldEqual(expectedMs); + } + + [TestCase] + public void DeferredMode_StopsBufferingAfterAttach() + { + using (JsonTracer tracer = JsonTracer.CreateDeferredForTesting("TestProvider", "StopBufferTest")) + using (MockListener listener = new MockListener(EventLevel.Verbose, Keywords.Telemetry)) + { + tracer.RelatedEvent(EventLevel.Informational, "BeforeAttach", metadata: null, keyword: Keywords.Telemetry); + tracer.TryAttachTestListener(listener).ShouldBeTrue(); + + // Events after attach go directly to listener, not buffered + tracer.RelatedEvent(EventLevel.Informational, "AfterAttach", metadata: null, keyword: Keywords.Telemetry); + + listener.EventNamesRead.Count.ShouldEqual(2); + listener.EventNamesRead.ShouldContain(name => name.Equals("BeforeAttach")); + listener.EventNamesRead.ShouldContain(name => name.Equals("AfterAttach")); + } + } + } +}