diff --git a/acceptance/localenv/cluster-name-ambiguous-json/output.txt b/acceptance/localenv/cluster-name-ambiguous-json/output.txt index ff557c87dea..cb5dcf04df7 100644 --- a/acceptance/localenv/cluster-name-ambiguous-json/output.txt +++ b/acceptance/localenv/cluster-name-ambiguous-json/output.txt @@ -38,5 +38,5 @@ "message": "resolving cluster name \"dup\": there are 2 active clusters named \"dup\"; use --cluster-id to disambiguate", "diskMutated": false }, - "durationMs": 0 + "durationMs": [DURATION_MS] } diff --git a/acceptance/localenv/constraints-only/output.txt b/acceptance/localenv/constraints-only/output.txt index e7a1c76529c..a98729c6ac2 100644 --- a/acceptance/localenv/constraints-only/output.txt +++ b/acceptance/localenv/constraints-only/output.txt @@ -49,5 +49,5 @@ ], "warnings": [], "error": null, - "durationMs": 0 + "durationMs": [DURATION_MS] } diff --git a/acceptance/localenv/flag-conflict-json/output.txt b/acceptance/localenv/flag-conflict-json/output.txt index 84840872e3f..5090f47dd70 100644 --- a/acceptance/localenv/flag-conflict-json/output.txt +++ b/acceptance/localenv/flag-conflict-json/output.txt @@ -38,5 +38,5 @@ "message": "invalid compute target flags: flags --cluster-id and --serverless-version are mutually exclusive; specify at most one", "diskMutated": false }, - "durationMs": 0 + "durationMs": [DURATION_MS] } diff --git a/acceptance/localenv/json-error/output.txt b/acceptance/localenv/json-error/output.txt index b2e5a0ba43e..7ea96c75f2d 100644 --- a/acceptance/localenv/json-error/output.txt +++ b/acceptance/localenv/json-error/output.txt @@ -38,5 +38,5 @@ "message": "No compute target is selected. Select a cluster or serverless target, or pass --cluster-id / --cluster-name / --serverless-version / --job-task", "diskMutated": false }, - "durationMs": 0 + "durationMs": [DURATION_MS] } diff --git a/acceptance/localenv/serverless-json/output.txt b/acceptance/localenv/serverless-json/output.txt index b0bc441a7c5..4b46fda397d 100644 --- a/acceptance/localenv/serverless-json/output.txt +++ b/acceptance/localenv/serverless-json/output.txt @@ -50,5 +50,5 @@ ], "warnings": [], "error": null, - "durationMs": 0 + "durationMs": [DURATION_MS] } diff --git a/acceptance/localenv/test.toml b/acceptance/localenv/test.toml new file mode 100644 index 00000000000..7ebbafd8c03 --- /dev/null +++ b/acceptance/localenv/test.toml @@ -0,0 +1,7 @@ +[[Repls]] +# environments setup-local emits a real wall-time durationMs; normalize it so the +# JSON goldens are deterministic. Order must beat the generic numeric repls +# (Order = 10 in the root test.toml), which would otherwise rewrite the digits first. +Old = '"durationMs": \d+' +New = '"durationMs": [DURATION_MS]' +Order = 8 diff --git a/libs/localenv/pipeline.go b/libs/localenv/pipeline.go index 30f803a21e4..cfaf4bc793b 100644 --- a/libs/localenv/pipeline.go +++ b/libs/localenv/pipeline.go @@ -8,6 +8,7 @@ import ( "os" "path/filepath" "strings" + "time" "github.com/databricks/cli/libs/log" "github.com/hexops/gotextdiff" @@ -81,6 +82,11 @@ func (p *Pipeline) Run(ctx context.Context) (*Result, error) { // Phases start as pending and flip to ok/error as the run progresses. p.res.Phases = initialPhases() + // Stamp wall time from a defer so every exit path is covered — success, a phase + // failure, and the cancellation reclassification below all return through it. + start := time.Now() + defer func() { p.res.DurationMs = time.Since(start).Milliseconds() }() + if err := p.run(ctx); err != nil { // A cancelled context means the user or parent interrupted us (SIGINT/ // SIGTERM). The phase that was running reports its own failure (e.g. uv diff --git a/libs/localenv/pipeline_test.go b/libs/localenv/pipeline_test.go index 865e4e30263..046cf4bbf15 100644 --- a/libs/localenv/pipeline_test.go +++ b/libs/localenv/pipeline_test.go @@ -10,6 +10,7 @@ import ( "runtime" "strings" "testing" + "time" "github.com/databricks/cli/libs/process" "github.com/stretchr/testify/assert" @@ -21,6 +22,11 @@ import ( // drop when it races with a Ctrl-C. const cancelPMStderr = "error: no solution found: databricks-connect==17.2 conflicts with pyspark==3.5" +// fetchDelay is injected into the constraint fetch by the duration tests. It gives +// each run a known minimum wall time, so the reported duration can be bounded from +// below — a plain ">= 0" assertion would also hold for the unset field. +const fetchDelay = 25 * time.Millisecond + type fakePM struct{ py, dbc string } func (fakePM) Name() string { return "fake" } @@ -156,6 +162,66 @@ func TestPipelineCheckMutatesNothing(t *testing.T) { assert.Empty(t, entries) } +// newSlowServer serves the constraint artifact after fetchDelay, replying with +// status so a caller can turn the fetch into a delayed failure. +func newSlowServer(t *testing.T, status int) *httptest.Server { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(fetchDelay) + w.WriteHeader(status) + _, _ = w.Write([]byte(sampleToml)) + })) + t.Cleanup(srv.Close) + return srv +} + +func TestPipelineReportsDuration(t *testing.T) { + // durationMs used to be hardcoded to 0, so a ">= 0" assertion would pass against + // the old behavior and prove nothing. Delay the constraint fetch instead: every + // run performs it, so the measured duration must exceed that delay while still + // fitting inside the wall time observed here. + dir := writeProject(t) + p := &Pipeline{ + Mode: ModeDefault, Check: true, ProjectDir: dir, + ConstraintBaseURL: newSlowServer(t, http.StatusOK).URL, CacheDir: t.TempDir(), + Flags: ComputeFlags{Serverless: "v4"}, + Compute: stubCompute{}, PM: fakePM{py: "3.12", dbc: "17.2.0"}, + } + before := time.Now() + res, err := p.Run(t.Context()) + elapsed := time.Since(before) + require.NoError(t, err) + assert.GreaterOrEqual(t, res.DurationMs, fetchDelay.Milliseconds(), + "duration must cover the delayed fetch, not report 0") + assert.LessOrEqual(t, res.DurationMs, elapsed.Milliseconds(), + "duration must not exceed the run's observed wall time") +} + +func TestPipelineReportsDurationOnFailure(t *testing.T) { + // The defer must cover the error paths too, so the --json consumer gets a + // duration even for a failed run. Fail *after* the delayed fetch rather than at + // preflight: a preflight error returns near-instantly, so its duration truncates + // to 0 and only a trivially-true bound would hold. A 500 with an empty cache is + // E_FETCH, which keeps a real lower bound on the failing path. + dir := writeProject(t) + p := &Pipeline{ + Mode: ModeDefault, Check: true, ProjectDir: dir, + ConstraintBaseURL: newSlowServer(t, http.StatusInternalServerError).URL, CacheDir: t.TempDir(), + Flags: ComputeFlags{Serverless: "v4"}, + Compute: stubCompute{}, PM: fakePM{py: "3.12", dbc: "17.2.0"}, + } + before := time.Now() + res, err := p.Run(t.Context()) + elapsed := time.Since(before) + + var pe *PipelineError + require.ErrorAs(t, err, &pe) + require.Equal(t, ErrFetch, pe.Code) + assert.GreaterOrEqual(t, res.DurationMs, fetchDelay.Milliseconds(), + "a failed run must still measure the work it did before failing, not report 0") + assert.LessOrEqual(t, res.DurationMs, elapsed.Milliseconds(), + "duration must not exceed the run's observed wall time") +} + func TestPipelineReportsCancellationNotProvisionFailure(t *testing.T) { // When the context is cancelled mid-provision (a Ctrl-C / SIGTERM), the run // must surface E_CANCELED, not E_PROVISION — the provision phase's own error diff --git a/libs/localenv/result.go b/libs/localenv/result.go index 244769727af..d50daed10a9 100644 --- a/libs/localenv/result.go +++ b/libs/localenv/result.go @@ -217,10 +217,9 @@ type Result struct { Warnings []Warning `json:"warnings"` Error *PipelineError `json:"error"` BackupPath string `json:"backupPath,omitempty"` - // DurationMs is part of the §6 contract but reserved for now: the pipeline - // does not measure wall time (a real clock would make acceptance goldens - // non-deterministic), so it is always emitted as 0 until timing is wired - // through a clock the tests can control. + // DurationMs is the pipeline's wall time in milliseconds (spec §6). It covers the + // CLI pipeline only; the extension measures its own end-to-end latency (process + // spawn, interpreter adoption) separately. DurationMs int64 `json:"durationMs"` }