From 0a855ea17876108d538738ceb2eddbf2c6be2827 Mon Sep 17 00:00:00 2001 From: Grigory Panov Date: Thu, 6 Aug 2026 14:58:27 +0200 Subject: [PATCH 1/2] localenv: populate setup-local durationMs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit durationMs was declared in the --output json contract but always emitted as 0, so the extension had no CLI-side latency figure to report (it backs the ERD's ~3-min setup claim). Stamp it from a defer in Pipeline.Run, which covers every exit path: success, a phase failure, and the E_CANCELED reclassification. The acceptance JSON goldens would otherwise carry a real, changing value, so a [DURATION_MS] repl normalizes it. It lives in acceptance/localenv/test.toml rather than the root: localenv is the only command emitting the key, and a global repl would silently normalize it for any future command without anyone opting in. Order = 8 beats the root's Order = 10 numeric repls, which would otherwise rewrite the digits first. Splitting this out from the warnings half of the same contract, which needs further work — they are independent fields and the durationMs change stands on its own. DECO-27875 Co-authored-by: Isaac --- .../cluster-name-ambiguous-json/output.txt | 2 +- .../localenv/constraints-only/output.txt | 2 +- .../localenv/flag-conflict-json/output.txt | 2 +- acceptance/localenv/json-error/output.txt | 2 +- .../localenv/serverless-json/output.txt | 2 +- acceptance/localenv/test.toml | 7 +++ libs/localenv/pipeline.go | 6 +++ libs/localenv/pipeline_test.go | 49 +++++++++++++++++++ libs/localenv/result.go | 7 ++- 9 files changed, 70 insertions(+), 9 deletions(-) create mode 100644 acceptance/localenv/test.toml 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..4c503605435 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" @@ -156,6 +157,54 @@ func TestPipelineCheckMutatesNothing(t *testing.T) { assert.Empty(t, entries) } +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. + const fetchDelay = 25 * time.Millisecond + dir := writeProject(t) + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(fetchDelay) + _, _ = w.Write([]byte(sampleToml)) + })) + defer srv.Close() + + p := &Pipeline{ + Mode: ModeDefault, Check: true, ProjectDir: dir, + ConstraintBaseURL: srv.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: a preflight usage error returns + // before any phase runs, and that Result still carries a duration for the + // --json consumer. Asserting the field is non-negative is trivially true, so + // bound it by the observed wall time — that catches an unset or garbage value. + dir := writeProject(t) + p := &Pipeline{ + Mode: ModeDefault, Check: true, ProjectDir: dir, CacheDir: t.TempDir(), + Flags: ComputeFlags{Cluster: "abc", 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.Error(t, err) + assert.LessOrEqual(t, res.DurationMs, elapsed.Milliseconds(), + "a failed run must report a plausible duration, not a stale or garbage value") +} + 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"` } From 5860bfb633b5b49c3457505f46da3d13b4e6ac8b Mon Sep 17 00:00:00 2001 From: Grigory Panov Date: Thu, 6 Aug 2026 15:46:49 +0200 Subject: [PATCH 2/2] localenv: assert a real lower bound on the failure-path duration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TestPipelineReportsDurationOnFailure only asserted DurationMs <= elapsed. An unset field is 0, which satisfies that bound trivially, so the test passed with the deferred stamp in Run deleted — it protected nothing on exactly the path it was named for. Fail after the delayed constraint fetch instead of at preflight. A preflight usage error returns near-instantly, so its duration truncates to 0 and no non-trivial lower bound exists; a 500 with an empty cache fails at the fetch phase with E_FETCH, after the run has done measurable work. Both duration tests now fail when the defer is removed. The 25ms delay and its server move to a shared const and helper, since both tests now need them. Co-authored-by: Isaac --- libs/localenv/pipeline_test.go | 49 +++++++++++++++++++++++----------- 1 file changed, 33 insertions(+), 16 deletions(-) diff --git a/libs/localenv/pipeline_test.go b/libs/localenv/pipeline_test.go index 4c503605435..046cf4bbf15 100644 --- a/libs/localenv/pipeline_test.go +++ b/libs/localenv/pipeline_test.go @@ -22,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" } @@ -157,22 +162,27 @@ 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. - const fetchDelay = 25 * time.Millisecond dir := writeProject(t) - srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - time.Sleep(fetchDelay) - _, _ = w.Write([]byte(sampleToml)) - })) - defer srv.Close() - p := &Pipeline{ Mode: ModeDefault, Check: true, ProjectDir: dir, - ConstraintBaseURL: srv.URL, CacheDir: t.TempDir(), + ConstraintBaseURL: newSlowServer(t, http.StatusOK).URL, CacheDir: t.TempDir(), Flags: ComputeFlags{Serverless: "v4"}, Compute: stubCompute{}, PM: fakePM{py: "3.12", dbc: "17.2.0"}, } @@ -187,22 +197,29 @@ func TestPipelineReportsDuration(t *testing.T) { } func TestPipelineReportsDurationOnFailure(t *testing.T) { - // The defer must cover the error paths too: a preflight usage error returns - // before any phase runs, and that Result still carries a duration for the - // --json consumer. Asserting the field is non-negative is trivially true, so - // bound it by the observed wall time — that catches an unset or garbage value. + // 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, CacheDir: t.TempDir(), - Flags: ComputeFlags{Cluster: "abc", Serverless: "v4"}, + 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) - require.Error(t, err) + + 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(), - "a failed run must report a plausible duration, not a stale or garbage value") + "duration must not exceed the run's observed wall time") } func TestPipelineReportsCancellationNotProvisionFailure(t *testing.T) {