Merge pull request #1724 from entireio/fix/450-hook-startup-latency · Entire

Merge pull request #1724 from entireio/fix/450-hook-startup-latency

61a0090→main·

suhaanthayyil·2d ago·11 files·+504 added/-116 removed

fix(hooks): cut synchronous work from session start/end paths

Changes

11

24 unmodified lines

25
26
27
28
28
29
30
31

24 unmodified lines

func isCheckpointPolicyWarningExcludedCommand(name string) bool {
    switch name {
    case "hooks", "__send_analytics", "curl-bash-post-install":
    case "hooks", "__send_analytics", "__refresh_trail_enablement", "curl-bash-post-install":
        return true
    default:
        return false
}

Mcmd/entire/cli/checkpoint_policy_warning.go+1/-1

46 unmodified lines

47
48
49
50
51
52
53
54
55
56
57
58

46 unmodified lines

sendAnalytics := &cobra.Command{Use: "__send_analytics", Hidden: true}
    root.AddCommand(sendAnalytics)

refreshTrailEnablement := &cobra.Command{Use: "__refresh_trail_enablement", Hidden: true}
    root.AddCommand(refreshTrailEnablement)

require.True(t, ShouldCheckCheckpointPolicyWarning(visible))
    require.True(t, ShouldCheckCheckpointPolicyWarning(hiddenAlias))
    require.False(t, ShouldCheckCheckpointPolicyWarning(gitHook))
    require.False(t, ShouldCheckCheckpointPolicyWarning(sendAnalytics))
    require.False(t, ShouldCheckCheckpointPolicyWarning(refreshTrailEnablement))
}

Mcmd/entire/cli/checkpoint_policy_warning_test.go+4

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49

package execx

import (
    "context"
    "io"
    "os"
    "os/exec"
    "testing"
)

// SpawnDetached re-execs the current executable as a detached, fire-and-forget
// child running args, surviving the parent's exit (new session on Unix,
// CREATE_NEW_PROCESS_GROUP | DETACHED_PROCESS on Windows, via detachFromTTY).
// The child runs in dir (os.TempDir() when empty, so the child never holds the
// parent's working directory), inherits the parent's environment, and has its
// stdout/stderr discarded. Best-effort: every error is swallowed — callers
// treat the spawn as advisory background work.
//
// In-process `go test` runs are a no-op: the current executable is the test
// binary, and re-execing it would fork the whole suite. Tests exercise the
// call sites through their spawn seams instead.
func SpawnDetached(dir string, args ...string) {
    if testing.Testing() {
        return
    }
    executable, err := os.Executable()
    if err != nil {
        return
    }

// context.Background(): the child must outlive the parent, so it is never
    // tied to a cancellable context.
    cmd := exec.CommandContext(context.Background(), executable, args...)
    detachFromTTY(cmd)
    cmd.Dir = dir
    if cmd.Dir == "" {
        cmd.Dir = os.TempDir()
    }
    cmd.Env = os.Environ()
    cmd.Stdout = io.Discard
    cmd.Stderr = io.Discard

if err := cmd.Start(); err != nil {
        return
    }
    // Release the process so it can run independently of the parent.
    //nolint:errcheck // best effort — the child continues regardless
    _ = cmd.Process.Release()
}

Acmd/entire/cli/execx/spawn_detached.go+49

110 unmodified lines

111
112
113
114
114
115
116
117
118
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
6 unmodified lines

145
146
147
148
149
150
151
152
153
12 unmodified lines

166
167
168
169
170
171
172
173
174

110 unmodified lines

}

// experimentalCommandMarkers are substrings that only appear in root help when
// experimental commands are visible.
// experimental commands are visible. Do not pin cobra's Use/Short column
// padding — group membership and longest-command width shift the spaces.
var experimentalCommandMarkers = []string{
    "Experimental commands:",
    "review",
    "tokens                 Analyze token usage across sessions and checkpoints",
}

// rootHelpHasTokensCommand reports whether root help lists the experimental
// `tokens` command with its Short description, ignoring Use/Short padding.
func rootHelpHasTokensCommand(got string) bool {
    for _, line := range strings.Split(got, "\n") {
        fields := strings.Fields(line)
        if len(fields) == 0 || fields[0] != "tokens" {
            continue
        }
        if strings.Contains(line, "Analyze token usage across sessions and checkpoints") {
            return true
        }
    }
    return false
}

// TestRootHelp_ReleaseHidesExperimental verifies a shipped build
// (experimental.Visible="false") omits experimental commands and the group
// header from root help. Mutates the global gate, so it cannot run in parallel.
6 unmodified lines

t.Fatalf("release root help should not include %q, got:\n%s", marker, got)
    }
}
if rootHelpHasTokensCommand(got) {
            t.Fatalf("release root help should not list tokens, got:\n%s", got)
    }
}

// TestRootHelp_DevShowsExperimentalGroup verifies a developer build
12 unmodified lines

t.Fatalf("dev root help should include %q, got:\n%s", marker, got)
    }
}
if !rootHelpHasTokensCommand(got) {
        t.Fatalf("dev root help should list tokens with its Short description, got:\n%s", got)
    }
}

// summaryColumns returns, for each non-empty rendered row, the rune offset at

Mcmd/entire/cli/labs_test.go+23/-2

1 unmodified line

2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
2212 unmodified lines

2235
2236
2237
2238
2239
2240
2241
2242
2243
2244
2245
2246
2247
2248
2249
2250
2251
2252
2253
2254
2255
2256
2257
2258
2259
2260
2261
2262
2263
2264
2265
2266
2267
2268
2269
2270
2271
2272
2273
2274
2275
2276
2277
2278
2279
2280
2281
2282
2283
2284
2285
2286
2287
2288
2289
2290
2291
2292
2293
2294
2295
2296
2297
2298
2299
2300
2301
2302
2303
2304
2305
2306
2307
2308
2309
2310
2311
2312
2313
2314
2315
2316
2317
2318
2319
2320
2321
2322
2323
2324
2325
2326
2327
2328
2329
2330
2331
2332
2333
2334
2335
2336
2337
2338
2339
2340
2341
2342
2343
2344
2345
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

1 unmodified line

import (
    "context"
    "net"
    "net/http"
    "net/http/httptest"
    "os"
    "os/exec"
    "path/filepath"
    "strings"
    "sync/atomic"
    "testing"
    "time"

"github.com/entireio/cli/cmd/entire/cli/agent"
    "github.com/entireio/cli/cmd/entire/cli/agent/opencode"
    "github.com/entireio/cli/cmd/entire/cli/agent/types"
    "github.com/entireio/cli/cmd/entire/cli/api"
    "github.com/entireio/cli/cmd/entire/cli/investigate"
    "github.com/entireio/cli/cmd/entire/cli/paths"
    "github.com/entireio/cli/cmd/entire/cli/review"
2212 unmodified lines

t.Fatalf("back-to-back checkpoint B after stale hook = %d, want 3", got)
    }
}

// TestHandleLifecycleSessionStart_NoSynchronousNetworkForTrailEnablement
// guards against SessionStart hooks stalling agent startup: the
// trails-enablement cache refresh must be handed off to a detached subprocess,
// never performed inline on the SessionStart hook path. A slow/unreachable API
// host previously added up to trailEnablementSessionStartRefreshTimeout (1s) of
// synchronous latency to every session start once the hourly cache went stale.
//
// The deterministic guarantee is the spawn seam: SessionStart must invoke the
// detached-refresh spawn exactly once and return without doing the network work
// itself. As a production-shaped backstop the API base points at a blackholed
// https host that accepts the TCP connection but never answers — so a
// regression that dials inline both contacts that host (dialed > 0) and burns
// the ~1s session-start budget instead of returning immediately. (Plain http
// would be rejected by api.RequireSecureURL before any dial, so the host must
// be https to actually exercise the synchronous-dial path.)
func TestHandleLifecycleSessionStart_NoSynchronousNetworkForTrailEnablement(t *testing.T) {
    setupStopTestRepo(t)
    runGitInDir(t, ".", "remote", "add", "origin", "https://github.com/entirehq/example.git")

// Blackhole https host: accept connections but never complete the TLS
    // handshake or respond, so an inline dial stalls until a timeout fires
    // (mirrors the unreachable-host case that motivated the detached refresh)
    // rather than failing fast.
    var dialed int32
    var lc net.ListenConfig
    ln, err := lc.Listen(context.Background(), "tcp", "127.0.0.1:0")
    require.NoError(t, err)
    defer ln.Close()
    go func() {
        for {
            conn, acceptErr := ln.Accept()
            if acceptErr != nil {
                return
            }
            atomic.AddInt32(&dialed, 1)
            _ = conn // hold open; never respond
        }
    }()
    t.Setenv("ENTIRE_API_BASE_URL", "https://"+ln.Addr().String())

var spawnCount int32
    prevSpawn := trailRefreshSpawn
    trailRefreshSpawn = func(worktreeRoot string) {
        atomic.AddInt32(&spawnCount, 1)
        if worktreeRoot == "" {
            t.Error("expected non-empty worktree root passed to trail refresh spawn")
        }
    }
t.Cleanup(func() { trailRefreshSpawn = prevSpawn })

ag := newMockHookResponseAgent()
    event := &agent.Event{
        Type:      agent.SessionStart,
        SessionID: "test-no-sync-trail-dial",
        Timestamp: time.Now(),
    }

start := time.Now()
    err = handleLifecycleSessionStart(context.Background(), ag, event)
elapsed := time.Since(start)

require.NoError(t, err)
    // Deterministic guarantee: the network-capable refresh is delegated to the
    // detached spawn exactly once, never run inline.
    if got := atomic.LoadInt32(&spawnCount); got != 1 {
        t.Fatalf("expected exactly one detached trail-enablement refresh spawn, got %d", got)
    }
    // Backstops: SessionStart neither contacted the API host nor blocked.
    if got := atomic.LoadInt32(&dialed); got != 0 {
        t.Fatalf("SessionStart dialed the trails-enablement API synchronously; the refresh must run out of process")
    }
    if elapsed > time.Second {
        t.Fatalf("handleLifecycleSessionStart took %v; trails-enablement refresh must be detached, not synchronous", elapsed)
    }
}

// TestRunTrailEnablementRefresh_BoundedByTimeoutAgainstUnresponsiveHost
// verifies the deferred refresh work still completes (or at least
// gives up) within its own bounded timeout when the API host never
// responds — the network work that used to block SessionStart must still
// happen, just out of the hook's critical path, and it must not hang forever.
func TestRunTrailEnablementRefresh_BoundedByTimeoutAgainstUnresponsiveHost(t *testing.T) {
    setupStopTestRepo(t)
    runGitInDir(t, ".", "remote", "add", "origin", "https://github.com/entirehq/example.git")

var lc net.ListenConfig
    ln, err := lc.Listen(context.Background(), "tcp", "127.0.0.1:0")
    require.NoError(t, err)
    defer ln.Close()
    var accepted int32
    go func() {
        for {
            conn, acceptErr := ln.Accept()
            if acceptErr != nil {
                return
            }
            atomic.AddInt32(&accepted, 1)
            // Accept the connection but never write anything back (no TLS
            // handshake, no HTTP response) — simulates a blackholed/firewalled
            // host, which is what triggered the original 1s stall per call.
            _ = conn
        }
    }()
    t.Setenv("ENTIRE_API_BASE_URL", "https://"+ln.Addr().String())

start := time.Now()
    refreshErr := runTrailEnablementRefresh(context.Background())
elapsed := time.Since(start)

// Best-effort: network failure must not surface as a hard error.
    require.NoError(t, refreshErr)
    if elapsed > trailEnablementRefreshTimeout+2*time.Second {
        t.Fatalf("runTrailEnablementRefresh took %v, expected to give up within roughly %v", elapsed, trailEnablementRefreshTimeout)
    }
    // Prove the test actually exercised the network path rather than passing
    // via an early return (e.g. scope resolution or auth failing before any
    // dial): the blackholed listener must have accepted at least one
    // connection attempt.
    if got := atomic.LoadInt32(&accepted); got == 0 {
        t.Fatalf("expected at least one dial attempt against the unresponsive host, got %d", got)
    }
}

// TestNewRefreshTrailEnablementCmd_APIFailureExitsZero guards against the
// detached __refresh_trail_enablement subprocess exiting non-zero on a
// transient network/API failure. The refresh is best-effort cache warming
// with stdout/stderr discarded (see newRefreshTrailEnablementCmd) — there is
// no one watching the exit code, so a failing TrailsEnabled call must be
// logged (already covered by TestRefreshTrailEnablementCmd_LogsBackgroundFailureToFile-
// style tests) and swallowed, never propagated as a command error.
func TestNewRefreshTrailEnablementCmd_APIFailureExitsZero(t *testing.T) {
    setupStopTestRepo(t)
    runGitInDir(t, ".", "remote", "add", "origin", "https://github.com/entirehq/example.git")

serv:= httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
        w.WriteHeader(http.StatusInternalServerError)
    }))
t.Cleanup(serv.Close)

prevClient := trailRefreshAPIClient
    trailRefreshAPIClient = func(context.Context, bool) (*api.Client, error) {
        return api.NewClientWithBaseURL("test-token", srv.URL), nil
    }
t.Cleanup(func() { trailRefreshAPIClient = prevClient })

cmd := newRefreshTrailEnablementCmd()
    cmd.SetArgs([]string{})
    require.NoError(t, cmd.ExecuteContext(context.Background()),
        "detached refresh command must exit 0 even when the API call fails (best-effort cache warming)")
}

// TestRefreshTrailEnablementCmd_LogsBackgroundFailureToFile guards
// diagnosability: 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")
}

// TestRefreshTrailEnablementCmd_NoStrayLogsOutsideWorktree guards the file-init
// against running outside a resolvable worktree. logging.Init falls back to the
// current directory when paths.WorktreeRoot fails, so the command must guard on
// WorktreeRoot (as resume/rewind/reset/explain do) or a child whose worktree was
// removed/relocated between spawn and exec would MkdirAll a stray .entire/logs/
// wherever it happens to be running.
func TestRefreshTrailEnablementCmd_NoStrayLogsOutsideWorktree(t *testing.T) {
    dir := t.TempDir() // a plain temp dir, not a git worktree
    t.Chdir(dir)
    paths.ClearWorktreeRootCache()
    session.ClearGitCommonDirCache()
    t.Setenv("ENTIRE_LOG_LEVEL", "debug")

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

_, statErr := os.Stat(filepath.Join(dir, ".entire", "logs"))
    require.True(t, os.IsNotExist(statErr),
        "must not create a stray .entire/logs outside a resolvable worktree")
}

// TestTrailRefreshRecentlySpawned_ThrottlesWithinWindow verifies the spawn-side
// guard: 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.
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)
    }
}