fix(hooks): make detached trail-refresh diagnosable and throttled

95dd5a5→main·

suhaanthayyil·6d ago·2 files·+137 added/-4 removed

Two re-analysis follow-ups to the #450 detached trails-enablement refresh.

Diagnosability: the __refresh_trail_enablement child runs with stdout/stderr discarded and never initialized file logging, and runTrailEnablementRefresh swallowed the scope/auth/network errors — so a failing background refresh (the exact #450 unreachable-host symptom) left no trace in .entire/logs/entire.log, stderr, or doctor bundles. The child now initializes file logging (mirroring the other hook-side commands) and the refresh logs its outcome at debug, restoring the diagnostic trail the inline path used to emit.

Spawn throttle: when the host is unreachable the refresh never writes the cache, so enablement stays unknown and the hourly TTL never starts — previously every SessionStart (and every concurrent worktree) forked a fresh child that re-opened the repo, re-resolved auth, and re-dialed the dead host. A flock-guarded per-repo marker keyed to the shared git-common-dir now collapses a burst of hooks to roughly one child per refresh-timeout window, while still retrying promptly once the host recovers.

Both paths stay best-effort: any error resolving, locking, or logging falls through to the prior behavior. Adds mutation-verified tests for the log trail, the throttle window, and the spawn-path wiring.

Changes

2

• cmd/entire/cli

• Mlifecycle_test.go+62

• Mtrail_context_cache.go+75/-4

2345 unmodified lines

2346
2347
2348
2349
2350
2351
2352
2353
2354
2355
2356
2357
2358
2359
2360
2361
2362
2363
2364
2365
2366
2367
2368
2369
2370
2371
2372
2373
2374
2375
2376
2377
2378
2379
2380
2381
2382
2383
2384
2385
2386
2387
2388
2389
2390
2391
2392
2393
2394
2395
2396
2397
2398
2399
2400
2401
2402
2403
2404
2405
2406
2407
2408
2409
2410

2345 unmodified lines

t.Fatalf("runTrailEnablementRefresh took %v, expected to give up within roughly %v", elapsed, trailEnablementRefreshTimeout)
    }

// TestRefreshTrailEnablementCmd_LogsBackgroundFailureToFile guards the #450 diagnosability fix: the detached __refresh_trail_enablement child runs with stdout/stderr discarded, so a failing background refresh must still leave a trail in .entire/logs/entire.log instead of vanishing. The command runs in a repo with no origin remote, so the scope resolves-and-fails locally (no network) and that failure has to be logged to the repo's log file.
func TestRefreshTrailEnablementCmd_LogsBackgroundFailureToFile(t *testing.T) {
    setupStopTestRepo(t)
    t.Setenv("ENTIRE_LOG_LEVEL", "debug")

cmd := newRefreshTrailEnablementCmd()
    cmd.SetArgs([]string{})
    require.NoError(t, cmd.ExecuteContext(context.Background()))

root, err := paths.WorktreeRoot(context.Background())
    require.NoError(t, err)
    logData, err := os.ReadFile(filepath.Join(root, ".entire", "logs", "entire.log"))
    require.NoError(t, err)
    require.Contains(t, string(logData), "trails enablement refresh skipped: scope unresolved",
        "background refresh failure must be diagnosable in .entire/logs/entire.log (#450)")
}

// TestTrailRefreshRecentlySpawned_ThrottlesWithinWindow verifies the spawn-side guard (#450 follow-up): within trailRefreshSpawnThrottle of a recorded spawn, further spawns are suppressed; once the window passes a fresh spawn is allowed and re-recorded. Without this, an unreachable host — which never writes the cache, so the hourly TTL never starts — would fork a refresh child on every SessionStart.
func TestTrailRefreshRecentlySpawned_ThrottlesWithinWindow(t *testing.T) {
    commonDir := t.TempDir()

now := time.Now()

require.False(t, trailRefreshRecentlySpawned(commonDir, now),
        "first call records the spawn and is not throttled")
    require.True(t, trailRefreshRecentlySpawned(commonDir, now.Add(time.Second)),
        "a second attempt within the window is throttled")
    require.False(t, trailRefreshRecentlySpawned(commonDir, now.Add(trailRefreshSpawnThrottle)),
        "at the window boundary the spawn is allowed and re-recorded")
    require.True(t, trailRefreshRecentlySpawned(commonDir, now.Add(trailRefreshSpawnThrottle+time.Second)),
        "an attempt within the window of the re-recorded spawn is throttled")
}

// TestSpawnDetachedTrailEnablementRefresh_CollapsesBurst verifies the throttle is actually wired into the spawn path: a burst of SessionStart-driven attempts for the same repo forks a single child, not one per hook (#450 follow-up).
func TestSpawnDetachedTrailEnablementRefresh_CollapsesBurst(t *testing.T) {
    setupStopTestRepo(t)

var spawnCount int32
    prevSpawn := trailRefreshSpawn
    trailRefreshSpawn = func(string) { atomic.AddInt32(&spawnCount, 1) }
    t.Cleanup(func() { trailRefreshSpawn = prevSpawn })

spawnDetachedTrailEnablementRefresh(context.Background())
    spawnDetachedTrailEnablementRefresh(context.Background())
    spawnDetachedTrailEnablementRefresh(context.Background())

if got := atomic.LoadInt32(&spawnCount); got != 1 {
            
t.Fatalf("expected the burst to collapse to a single detached spawn, got %d", got)
    }
}

Mcmd/entire/cli/lifecycle_test.go+62

13 unmodified lines

14
15
16
17
18
19
20
206 unmodified lines

227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
6 unmodified lines

248
249
250
251
252
253
245
246
254
255
256
257
258
259
260
261
262
3 unmodified lines

266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
259
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
4 unmodified lines

337
338
339
278
340
341
342
343
344
345
346
347
348
349
350
351
352

13 unmodified lines

"github.com/entireio/cli/cmd/entire/cli/api"
    "github.com/entireio/cli/cmd/entire/cli/auth"
    "github.com/entireio/cli/cmd/entire/cli/gitremote"
    "github.com/entireio/cli/cmd/entire/cli/internal/flock"
    "github.com/entireio/cli/cmd/entire/cli/jsonutil"
    "github.com/entireio/cli/cmd/entire/cli/logging"
    "github.com/entireio/cli/cmd/entire/cli/paths"
206 unmodified lines

ctx, cancel := context.WithTimeout(ctx, trailEnablementRefreshTimeout)
    defer cancel()

// This runs detached with stdout/stderr discarded, so log at debug to the
    // repo's .entire/logs/entire.log (initialized by newRefreshTrailEnablementCmd).
    // Without this, an unreachable/failing host — the exact #450 symptom — would
    // leave the background refresh silently failing with no diagnostic trail.
    logCtx := logging.WithComponent(ctx, "trail-refresh")

scope, err := currentTrailEnablementScope(ctx)
    if err != nil {
        logging.Debug(logCtx, "trails enablement refresh skipped: scope unresolved", "error", err.Error())
        return nil
    }
    // Another process (e.g. a fast-following SessionStart, or a concurrent
6 unmodified lines

}
    client, err := NewAuthenticatedAPIClient(ctx, false)
    if err != nil {
        logging.Debug(logCtx, "trails enablement refresh skipped: authenticated client unavailable", "error", err.Error())
        return nil
    }
    _, err = refreshTrailsEnabledCacheForScope(ctx, client, scope)
    return err
    if _, err := refreshTrailsEnabledCacheForScope(ctx, client, scope); err != nil {
        logging.Debug(logCtx, "trails enablement refresh failed", "error", err.Error())
        return err
    }
    logging.Debug(logCtx, "trails enablement refresh completed", "enabled_repo_key", scope.RepoKey)
    return nil
}

// trailRefreshSpawn is the process-spawn seam used by

// argument). Production code always uses spawnDetachedTrailRefreshProcess.
var trailRefreshSpawn = spawnDetachedTrailRefreshProcess

// trailRefreshSpawnThrottle bounds how often SessionStart forks a detached
// refresh child for a given repo. When the API host is unreachable the refresh
// never writes the cache, so cachedTrailsEnablementForScope stays unknown and
// the hourly TTL never starts — without this guard every SessionStart (and
// every concurrent worktree) would fork a fresh child that re-opens the repo,
// re-resolves auth, and re-dials the dead host. Tying the window to the child's
// own timeout collapses a burst of hooks to roughly one child per window while
// still retrying promptly once the host recovers.
const trailRefreshSpawnThrottle = trailEnablementRefreshTimeout

// spawnDetachedTrailEnablementRefresh starts a detached child process that
// runs runTrailEnablementRefresh in the background. Best-effort: if the
// worktree root can't be resolved or the subprocess can't be spawned, the
// cache simply stays unknown and the next SessionStart tries again.
// cache simply stays unknown and the next SessionStart tries again. A recent
// spawn for the same repo short-circuits so a burst of hooks doesn't fork a
// herd of redundant refresh children (see trailRefreshRecentlySpawned).
func spawnDetachedTrailEnablementRefresh(ctx context.Context) {
    worktreeRoot, err := paths.WorktreeRoot(ctx)
    if err != nil {
        return
    }
    if commonDir, err := session.GetGitCommonDir(ctx); err == nil &&
        trailRefreshRecentlySpawned(commonDir, time.Now()) {
        return
    }
    trailRefreshSpawn(worktreeRoot)
}

// trailRefreshRecentlySpawned reports whether a detached refresh was spawned for
// this repo within trailRefreshSpawnThrottle and, when it wasn't, records now as
// the most recent spawn. The read-and-record is serialized with a flock keyed to
// the shared git-common-dir (so every worktree of the repo agrees), collapsing a
// burst of concurrent SessionStart hooks to a single child rather than one per
// hook. Best-effort: any error resolving, locking, or writing the marker falls
// through to spawning — never worse than before this guard existed.
func trailRefreshRecentlySpawned(commonDir string, now time.Time) bool {
    dir := filepath.Join(commonDir, "entire")
    // Create the directory before acquiring the lock: flock.Acquire opens the
    // lock file, which fails if its parent doesn't exist yet (mirrors
    // ModifyClonePreferences, which MkdirAlls before locking).
    if err := os.MkdirAll(dir, 0o750); err != nil {
        return false
    }
    markerPath := filepath.Join(dir, "trail-refresh-spawn")
    release, err := flock.Acquire(markerPath + ".lock")
    if err != nil {
        return false
    }
    defer release()

if data, readErr := os.ReadFile(markerPath); readErr == nil { //nolint:gosec // markerPath is derived from the trusted git-common-dir, not user input
        if last, parseErr := time.Parse(time.RFC3339Nano, strings.TrimSpace(string(data))); parseErr == nil &&
            now.After(last) && now.Sub(last) < trailRefreshSpawnThrottle {
            return true
        }
    }
    //nolint:errcheck // best-effort marker; a failed write just means the next hook re-spawns
    _ = os.WriteFile(markerPath, []byte(now.UTC().Format(time.RFC3339Nano)), 0o600)
    return false
}

// newRefreshTrailEnablementCmd creates the hidden command that performs the
// (potentially slow) trails-enablement network refresh out of band. It is
// invoked by spawnDetachedTrailEnablementRefresh from a detached subprocess
4 unmodified lines

Hidden: true,
    Args:   cobra.NoArgs,
    RunE: func(cmd *cobra.Command, _ []string) error {
        return runTrailEnablementRefresh(cmd.Context())
        ctx := cmd.Context()
        // Detached child with discarded stdout/stderr: initialize file
        // logging so a failing background refresh (the #450 unreachable-host
        // symptom) is diagnosable in .entire/logs/entire.log rather than
        // vanishing. Best-effort, mirroring the other hook-side commands.
        logging.SetLogLevelGetter(GetLogLevel)
        if err := logging.Init(ctx, ""); err == nil {
            defer logging.Close()
        }
        return runTrailEnablementRefresh(ctx)
    },
}