From b4b5be32e7df37046be5b8464d17f9469a04ee07 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Thu, 21 May 2026 14:30:44 -0700 Subject: [PATCH 1/3] Defer telemetry pipe attachment for GVFS.Service MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GVFS.Service runs as SYSTEM and cannot read the user's global git config (where gvfs.telemetry-pipe is set). This meant the TelemetryDaemonEventListener was never created, and all service telemetry events (PendingUpgradeHandler, etc.) were silently lost. When the pipe config is unavailable at construction time, JsonTracer now defers listener creation and buffers up to 1000 telemetry messages. TryAttachTelemetryPipe() can be called later when a user session is available to read the config and replay buffered events. GVFSService calls TryAttachTelemetryPipeForSession() both at startup (if a user is already logged in) and on SessionLogon. It temporarily sets HOME to the user's profile directory so git can locate .gitconfig — RunImpersonated alone doesn't load the user environment. Assisted-by: Claude Opus 4.6 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/NativeMethods.cs | 13 ++++ GVFS/GVFS.Common/Tracing/JsonTracer.cs | 92 ++++++++++++++++++++++++ GVFS/GVFS.Service/GVFSService.Windows.cs | 68 ++++++++++++++++++ 3 files changed, 173 insertions(+) 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..67f64ee90 100644 --- a/GVFS/GVFS.Common/Tracing/JsonTracer.cs +++ b/GVFS/GVFS.Common/Tracing/JsonTracer.cs @@ -22,6 +22,17 @@ 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), buffer telemetry messages and replay them when + // TryAttachTelemetryPipe() is called with valid config access. + private string deferredProviderName; + private string deferredEnlistmentId; + private string deferredMountId; + private ConcurrentQueue deferredMessages; + private readonly Lock deferredLock = new Lock(); + private const int MaxDeferredMessages = 1000; + private bool isDisposed = false; private bool stopped = false; @@ -59,6 +70,17 @@ 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). Defer listener + // creation — buffer telemetry messages until + // TryAttachTelemetryPipe() succeeds. + this.deferredProviderName = providerName; + this.deferredEnlistmentId = enlistmentId; + this.deferredMountId = mountId; + this.deferredMessages = new ConcurrentQueue(); + } } } @@ -394,6 +416,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 +438,63 @@ 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; + + while (queue.TryDequeue(out TraceEventMessage message)) + { + daemonListener.RecordMessage(message); + } + + return true; + } + } } } 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; From e272141e981a0ba00b6262dd9f3127d7fde16e6e Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Fri, 22 May 2026 14:52:46 -0700 Subject: [PATCH 2/3] Add periodic retry for deferred telemetry pipe attachment MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When the telemetry collector (GitService) is installed while a GVFS.Mount or GVFS.Service process is already running, the pipe config (gvfs.telemetry-pipe) appears in git config after the tracer was constructed. Without a retry mechanism, the process would never connect and telemetry would be silently lost. Start a retry timer when entering deferred mode. Uses exponential backoff: 10s, 30s, 1m, then 5m steady state. The timer calls TryAttachTelemetryPipe with the stashed gitBinRoot. On success, buffered messages are replayed and the timer stops. The timer is also cleaned up on dispose. For GVFS.Service (SYSTEM account), the retry timer alone cannot read the user's global config — the explicit session-based attach from commit 1 handles that case. The timer covers mount processes that start before GitService is installed. Assisted-by: Claude Opus 4.6 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/Tracing/JsonTracer.cs | 86 ++++++++++++++++++++++++-- 1 file changed, 81 insertions(+), 5 deletions(-) diff --git a/GVFS/GVFS.Common/Tracing/JsonTracer.cs b/GVFS/GVFS.Common/Tracing/JsonTracer.cs index 67f64ee90..73edb0a3c 100644 --- a/GVFS/GVFS.Common/Tracing/JsonTracer.cs +++ b/GVFS/GVFS.Common/Tracing/JsonTracer.cs @@ -24,13 +24,17 @@ public class JsonTracer : ITracer, IEventListenerEventSink // 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), buffer telemetry messages and replay them when - // TryAttachTelemetryPipe() is called with valid config access. + // 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; @@ -73,13 +77,16 @@ public JsonTracer(string providerName, Guid providerActivityId, string activityN else { // Pipe config not available (e.g. running as SYSTEM without - // access to user's global git config). Defer listener - // creation — buffer telemetry messages until - // TryAttachTelemetryPipe() succeeds. + // 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(); } } } @@ -154,6 +161,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) { @@ -487,6 +499,7 @@ public bool TryAttachTelemetryPipe(string gitBinRoot) // Replay buffered messages then stop buffering ConcurrentQueue queue = this.deferredMessages; this.deferredMessages = null; + this.StopDeferredRetryTimer(); while (queue.TryDequeue(out TraceEventMessage message)) { @@ -496,5 +509,68 @@ public bool TryAttachTelemetryPipe(string gitBinRoot) 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); + } + } + } + } + + private 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 + }; + } } } From 6e409de2a8a9f6361bb15fe7986cfb3186137c5f Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Fri, 22 May 2026 15:16:38 -0700 Subject: [PATCH 3/3] Add unit tests for deferred telemetry pipe attachment Cover the buffering, replay, cap, and retry interval logic added in the previous commits. Test seams (CreateDeferredForTesting, TryAttachTestListener, GetRetryInterval) are internal so only the unit test assembly can use them. Tests: - Buffer and replay telemetry messages on attach - Non-telemetry messages are not buffered - Buffer caps at 1000 messages - Second attach attempt returns false - Null/empty gitBinRoot returns false - Retry interval exponential backoff values - Events after attach go directly to listener Assisted-by: Claude Opus 4.6 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/Tracing/JsonTracer.cs | 42 +++++- .../Common/JsonTracerDeferredTests.cs | 137 ++++++++++++++++++ 2 files changed, 178 insertions(+), 1 deletion(-) create mode 100644 GVFS/GVFS.UnitTests/Common/JsonTracerDeferredTests.cs diff --git a/GVFS/GVFS.Common/Tracing/JsonTracer.cs b/GVFS/GVFS.Common/Tracing/JsonTracer.cs index 73edb0a3c..bdc7e6c2d 100644 --- a/GVFS/GVFS.Common/Tracing/JsonTracer.cs +++ b/GVFS/GVFS.Common/Tracing/JsonTracer.cs @@ -91,6 +91,46 @@ public JsonTracer(string providerName, Guid providerActivityId, string activityN } } + /// + /// 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; + } + } + private JsonTracer(ConcurrentBag listeners, Guid parentActivityId, string activityName, EventLevel startStopLevel, Keywords startStopKeywords) { this.listeners = listeners ?? new ConcurrentBag(); @@ -562,7 +602,7 @@ private void OnDeferredRetryTimer(object state) } } - private static int GetRetryInterval(int retryCount) + internal static int GetRetryInterval(int retryCount) { return retryCount switch { 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")); + } + } + } +}