diff --git a/commands/apply.go b/commands/apply.go index 96650a6..61c469d 100644 --- a/commands/apply.go +++ b/commands/apply.go @@ -468,12 +468,19 @@ func (c *ApplyCommand) executeLeafTask(env *tasks.TaskEnvelope, name string, ac } if msg := tasks.TaskDeprecation(env.Task); msg != "" { - ac.emitter.TaskWarning(ac.play.Name, name, msg) + ac.emitter.TaskWarning(ac.play.Name, name, "deprecated", msg) } state := env.Task.Execute() ac.counts.Tasks++ + // Probe diagnostics raised during planning (carried out on the state by + // ExecutePlan) surface as informational warning lines/events above the + // task's own result line. + for _, w := range state.Warnings { + ac.emitter.TaskWarning(ac.play.Name, name, w.Reason, w.Message) + } + postState, overrideErr := applyEnvelopeOverrides(env, state, ac.playExprCtx, ac.registered, failedTask) if overrideErr != nil { ac.counts.Errors++ diff --git a/commands/export.go b/commands/export.go index 0b5aafe..f29c748 100644 --- a/commands/export.go +++ b/commands/export.go @@ -131,7 +131,7 @@ func (c *ExportCommand) Run(args []string) int { return 1 } for _, w := range res.Report.Warnings { - c.Ui.Warn(fmt.Sprintf("warning: %s", w)) + c.Ui.Warn(fmt.Sprintf("warning: %s", subprocess.MaskString(w))) } // A nonexistent --app must not silently produce an empty recipe (which the diff --git a/commands/output.go b/commands/output.go index ccaba6e..2e8f2d5 100644 --- a/commands/output.go +++ b/commands/output.go @@ -30,10 +30,13 @@ type EventEmitter interface { // PlanTask emits one event per task in a `plan` run. PlanTask(ev PlanTaskEvent) // TaskWarning emits a non-fatal warning associated with a task, such - // as a task-type deprecation notice. It does not affect task counts - // or exit codes; apply / plan call it before the per-task event so - // the warning appears immediately above the task's result line. - TaskWarning(play, name, message string) + // as a task-type deprecation notice or a property probe diagnostic. It + // does not affect task counts or exit codes. reason is a stable machine + // key ("deprecated", or a tasks.WarnReason* value) the JSON emitter + // surfaces and the human emitter maps to a marker. The warning is + // emitted before the per-task event so it appears above the task's + // result line. + TaskWarning(play, name, reason, message string) // ApplySummary emits the end-of-run footer for `apply`. ApplySummary(c ApplyCounts, d time.Duration) // PlanSummary emits the end-of-run footer for `plan`. @@ -134,6 +137,12 @@ const ( // markers because the warning is informational and does not feed // the run counts or exit code. MarkerDeprecated Marker = "deprecated" + + // MarkerWarning prefixes a TaskWarning line for a non-deprecation + // diagnostic (for example a property probe that found no matching + // report key). Like MarkerDeprecated it is informational and does not + // feed the run counts or exit code. + MarkerWarning Marker = "warning" ) // markerWidth is the fixed column width that every bracketed marker is @@ -200,20 +209,26 @@ func NewFormatter(ui cli.Ui, verbose bool) *Formatter { MarkerDestroy: color.New(color.FgRed), MarkerProbeError: color.New(color.FgRed), MarkerDeprecated: color.New(color.FgYellow, color.Faint), + MarkerWarning: color.New(color.FgYellow, color.Faint), }, } } -// TaskWarning renders a `[deprecated] ()` line above the +// TaskWarning renders a `[] ()` line above the // task's result line. It is informational, so the line goes to -// Ui.Output (not Ui.Error) and does not affect counts. The message is -// masked against the global sensitive set. -func (f *Formatter) TaskWarning(_, name, message string) { +// Ui.Output (not Ui.Error) and does not affect counts. The marker is +// `[deprecated]` for a deprecation notice and `[warning]` for any other +// diagnostic. The message is masked against the global sensitive set. +func (f *Formatter) TaskWarning(_, name, reason, message string) { if message == "" { return } + marker := MarkerWarning + if reason == "deprecated" { + marker = MarkerDeprecated + } suffix := "(" + message + ")" - f.TaskLine(MarkerDeprecated, name, suffix) + f.TaskLine(marker, name, suffix) } // Verbose reports whether the formatter is in verbose mode. diff --git a/commands/output_json.go b/commands/output_json.go index 1672708..34fc71f 100644 --- a/commands/output_json.go +++ b/commands/output_json.go @@ -175,10 +175,11 @@ func (e *JSONEmitter) PlanTask(ev PlanTaskEvent) { } // TaskWarning emits a `warning` event keyed by `reason` and tied to a -// specific task. Today the only reason is "deprecated"; the event is -// emitted before the task's own `task` event so consumers can correlate -// by ordering. -func (e *JSONEmitter) TaskWarning(play, name, message string) { +// specific task. reason is "deprecated" for a deprecation notice or a +// tasks.WarnReason* value for a probe diagnostic; the event is emitted +// before the task's own `task` event so consumers can correlate by +// ordering. +func (e *JSONEmitter) TaskWarning(play, name, reason, message string) { if message == "" { return } @@ -187,7 +188,7 @@ func (e *JSONEmitter) TaskWarning(play, name, message string) { "type": "warning", "play": subprocess.MaskString(play), "name": subprocess.MaskString(name), - "reason": "deprecated", + "reason": reason, "message": subprocess.MaskString(message), "ts": nowRFC3339(), }) diff --git a/commands/output_json_test.go b/commands/output_json_test.go index be0b3cf..a16fb11 100644 --- a/commands/output_json_test.go +++ b/commands/output_json_test.go @@ -450,7 +450,7 @@ func TestJSONEmitterEveryEventHasVersion1(t *testing.T) { // TestEmitterInterfaceSatisfied compiles iff Formatter and JSONEmitter both func TestJSONEmitterTaskWarning(t *testing.T) { e, ui := emitterTestUI() - e.TaskWarning("tasks", "ensure storage", "use dokku_storage_entry instead") + e.TaskWarning("tasks", "ensure storage", "deprecated", "use dokku_storage_entry instead") ev := decodeOnly(t, ui.OutputWriter.String()) if got, want := ev["version"], float64(1); got != want { @@ -478,12 +478,33 @@ func TestJSONEmitterTaskWarning(t *testing.T) { func TestJSONEmitterTaskWarningEmptyIsNoOp(t *testing.T) { e, ui := emitterTestUI() - e.TaskWarning("tasks", "ensure storage", "") + e.TaskWarning("tasks", "ensure storage", "deprecated", "") if ui.OutputWriter.String() != "" { t.Errorf("expected no output for empty message, got %q", ui.OutputWriter.String()) } } +// TestJSONEmitterTaskWarningProbeReason pins that a non-deprecation warning +// carries its own reason through the event and that the message is masked. (#353) +func TestJSONEmitterTaskWarningProbeReason(t *testing.T) { + subprocess.SetGlobalSensitive([]string{"s3cr3t"}) + t.Cleanup(func() { subprocess.SetGlobalSensitive(nil) }) + + e, ui := emitterTestUI() + e.TaskWarning("tasks", "set token", "probe_rejected", "rejected probe near value s3cr3t") + ev := decodeOnly(t, ui.OutputWriter.String()) + + if got, want := ev["reason"], "probe_rejected"; got != want { + t.Errorf("reason = %v, want %v", got, want) + } + if msg, _ := ev["message"].(string); strings.Contains(msg, "s3cr3t") { + t.Errorf("message leaked secret: %q", msg) + } + if msg, _ := ev["message"].(string); !strings.Contains(msg, "***") { + t.Errorf("message should carry mask placeholder, got %q", msg) + } +} + // satisfy the EventEmitter contract. Catches signature drift at build time. func TestEmitterInterfaceSatisfied(t *testing.T) { var _ EventEmitter = (*Formatter)(nil) diff --git a/commands/output_test.go b/commands/output_test.go index de3e1d1..a51c959 100644 --- a/commands/output_test.go +++ b/commands/output_test.go @@ -382,7 +382,7 @@ func TestApplyTaskErrorOmitsEmptyStdout(t *testing.T) { func TestFormatterTaskWarningRendersDeprecatedMarker(t *testing.T) { f, ui := newTestFormatter(false) - f.TaskWarning("tasks", "ensure storage", "use dokku_storage_entry instead") + f.TaskWarning("tasks", "ensure storage", "deprecated", "use dokku_storage_entry instead") got := ui.OutputWriter.String() if !strings.Contains(got, "[deprecated]") { t.Errorf("expected [deprecated] marker, got %q", got) @@ -398,9 +398,36 @@ func TestFormatterTaskWarningRendersDeprecatedMarker(t *testing.T) { } } +// TestFormatterTaskWarningRendersWarningMarker pins that a non-deprecation +// reason renders the [warning] marker (not [deprecated]) on stdout, and masks +// the message. (#353) +func TestFormatterTaskWarningRendersWarningMarker(t *testing.T) { + subprocess.SetGlobalSensitive([]string{"s3cr3t"}) + t.Cleanup(func() { subprocess.SetGlobalSensitive(nil) }) + + f, ui := newTestFormatter(false) + f.TaskWarning("tasks", "set token", "probe_rejected", "rejected probe near value s3cr3t") + got := ui.OutputWriter.String() + if !strings.Contains(got, "[warning]") { + t.Errorf("expected [warning] marker, got %q", got) + } + if strings.Contains(got, "[deprecated]") { + t.Errorf("non-deprecation warning must not use [deprecated], got %q", got) + } + if strings.Contains(got, "s3cr3t") { + t.Errorf("warning line leaked secret: %q", got) + } + if !strings.Contains(got, "***") { + t.Errorf("expected masked placeholder in line, got %q", got) + } + if ui.ErrorWriter.String() != "" { + t.Errorf("informational warning must not write to stderr, got %q", ui.ErrorWriter.String()) + } +} + func TestFormatterTaskWarningEmptyMessageIsNoOp(t *testing.T) { f, ui := newTestFormatter(false) - f.TaskWarning("tasks", "ensure storage", "") + f.TaskWarning("tasks", "ensure storage", "deprecated", "") if ui.OutputWriter.String() != "" { t.Errorf("expected no output for empty message, got %q", ui.OutputWriter.String()) } diff --git a/commands/plan.go b/commands/plan.go index 541e211..55168fd 100644 --- a/commands/plan.go +++ b/commands/plan.go @@ -393,12 +393,18 @@ func planLeaf(env *tasks.TaskEnvelope, name string, pc *planContext, failedTask } if msg := tasks.TaskDeprecation(env.Task); msg != "" { - pc.emitter.TaskWarning(pc.play.Name, name, msg) + pc.emitter.TaskWarning(pc.play.Name, name, "deprecated", msg) } result := env.Task.Plan() pc.counts.Tasks++ + // Probe diagnostics raised during planning surface as informational + // warning lines/events above the task's own result line. + for _, w := range result.Warnings { + pc.emitter.TaskWarning(pc.play.Name, name, w.Reason, w.Message) + } + synth := tasks.TaskOutputState{ Changed: !result.InSync, Error: result.Error, diff --git a/commands/stub_task_test.go b/commands/stub_task_test.go index 657ce68..7829aec 100644 --- a/commands/stub_task_test.go +++ b/commands/stub_task_test.go @@ -46,6 +46,7 @@ func (t StubTask) Plan() tasks.PlanResult { return tasks.PlanResult{ Status: tasks.PlanStatusModify, DesiredState: tasks.StatePresent, + Warnings: fixture.Warnings, } } @@ -85,6 +86,7 @@ func (t StubTask) Execute() tasks.TaskOutputState { Stdout: fixture.Stdout, Stderr: fixture.Stderr, ExitCode: fixture.ExitCode, + Warnings: fixture.Warnings, } } @@ -99,6 +101,10 @@ type StubFixture struct { Stderr string ExitCode int MismatchState bool + // Warnings are echoed onto the drift PlanResult (plan mode) and the + // success TaskOutputState (apply mode) so tests can drive the run loops' + // warning drain. #353. + Warnings []tasks.PlanWarning } var ( diff --git a/commands/task_warning_test.go b/commands/task_warning_test.go new file mode 100644 index 0000000..75e82ae --- /dev/null +++ b/commands/task_warning_test.go @@ -0,0 +1,99 @@ +package commands + +import ( + "strings" + "testing" + + "github.com/dokku/docket/tasks" +) + +// These tests pin #353: a probe diagnostic a task's Plan() surfaces on +// PlanResult.Warnings (carried onto TaskOutputState for apply) is drained by +// the run loops through EventEmitter.TaskWarning, so it renders as a `[warning]` +// line (human) / `warning` event (JSON) correlated with its task rather than a +// raw log line. Masking is covered by the emitter-level tests; here we pin the +// routing, the reason, and the "warning precedes task" ordering. + +const probeWarningMessage = "dokku registry:report rejected probe for property \"password\"" + +func stubWithWarning() StubFixture { + return StubFixture{ + Changed: true, + Warnings: []tasks.PlanWarning{ + {Reason: tasks.WarnReasonProbeRejected, Message: probeWarningMessage}, + }, + } +} + +const warningRecipe = `--- +- tasks: + - name: set token + dokku_stub: { key: a } +` + +func TestPlanSurfacesProbeWarning(t *testing.T) { + defer stubReset() + stubSet("a", stubWithWarning()) + path := writeTasksFile(t, warningRecipe) + + stdout, _, _ := runPlan(t, path) + if !strings.Contains(stdout, "[warning]") { + t.Errorf("expected [warning] line in plan output; got:\n%s", stdout) + } + if !strings.Contains(stdout, probeWarningMessage) { + t.Errorf("expected warning message in plan output; got:\n%s", stdout) + } + // The warning line must precede the task's own result line. + if wi, ti := strings.Index(stdout, "[warning]"), strings.Index(stdout, "[~]"); wi < 0 || ti < 0 || wi > ti { + t.Errorf("warning should precede the task line; got:\n%s", stdout) + } + + jsonOut, _, _ := runPlan(t, path, "--json") + assertWarningEventPrecedesTask(t, jsonOut) +} + +func TestApplySurfacesProbeWarning(t *testing.T) { + defer stubReset() + stubSet("a", stubWithWarning()) + path := writeTasksFile(t, warningRecipe) + + stdout, _, _ := runApply(t, path) + if !strings.Contains(stdout, "[warning]") { + t.Errorf("expected [warning] line in apply output; got:\n%s", stdout) + } + if !strings.Contains(stdout, probeWarningMessage) { + t.Errorf("expected warning message in apply output; got:\n%s", stdout) + } + + jsonOut, _, _ := runApply(t, path, "--json") + assertWarningEventPrecedesTask(t, jsonOut) +} + +// assertWarningEventPrecedesTask checks the JSON stream carries a `warning` +// event with the probe reason and message, emitted before its `task` event. +func assertWarningEventPrecedesTask(t *testing.T, jsonOut string) { + t.Helper() + warnIdx, taskIdx := -1, -1 + for i, ev := range decodeLines(t, jsonOut) { + switch ev["type"] { + case "warning": + warnIdx = i + if ev["reason"] != tasks.WarnReasonProbeRejected { + t.Errorf("warning reason = %v, want %v", ev["reason"], tasks.WarnReasonProbeRejected) + } + if msg, _ := ev["message"].(string); !strings.Contains(msg, probeWarningMessage) { + t.Errorf("warning message = %q, want to contain %q", msg, probeWarningMessage) + } + case "task": + if taskIdx == -1 { + taskIdx = i + } + } + } + if warnIdx == -1 { + t.Fatalf("no warning event in JSON stream:\n%s", jsonOut) + } + if taskIdx == -1 || warnIdx > taskIdx { + t.Errorf("warning event should precede task event; warnIdx=%d taskIdx=%d\n%s", warnIdx, taskIdx, jsonOut) + } +} diff --git a/docs/command-reference.md b/docs/command-reference.md index fb7482a..095f655 100644 --- a/docs/command-reference.md +++ b/docs/command-reference.md @@ -133,6 +133,10 @@ layout as `apply`, with a marker set focused on drift: | `[-]` | `apply` would remove existing state. | | `[!]` | The read-state probe itself errored, so drift is unknown. | +A task may also be preceded by an informational `[deprecated]` or `[warning]` line (a task-type +deprecation notice, or a property probe diagnostic such as an unknown report key). These do not +count toward the summary or the exit code. + Tasks that perform several operations itemize them under the task line: ```text @@ -184,6 +188,9 @@ gets a status marker: | `[skipped]` | Filtered out by `when:` or `--start-at-task`. | | `[error]` | Errored. | +As in `plan`, a task may be preceded by an informational `[deprecated]` or `[warning]` line that +does not count toward the summary or the exit code. + A play header precedes the task lines, and a summary closes the run: ```text diff --git a/docs/json-output.md b/docs/json-output.md index df9a69b..2a602e2 100644 --- a/docs/json-output.md +++ b/docs/json-output.md @@ -27,11 +27,18 @@ slightly between `apply` and `plan`: | `summary` (plan) | `version`, `type`, `tasks`, `would_change`, `in_sync`, `skipped`, `errors`, `plays_skipped`, `duration_ms` | - | A `warning` event precedes the `task` event it is associated with so consumers can correlate by -ordering. Today the only `reason` is `deprecated`, emitted when a task whose type implements -`Deprecation()` is about to run; `message` carries the deprecation notice with sensitive values -masked. `--list-tasks --json` does not emit a separate `warning` event; instead, the `list_task` -event for a deprecated task carries `"deprecated": true` and a `deprecation` field with the -message. +ordering. The `reason` is a stable machine key so consumers can branch on the category: + +| `reason` | Emitted when | +|----------|--------------| +| `deprecated` | A task whose type implements `Deprecation()` is about to run; `message` carries the deprecation notice. | +| `unknown_property` | A property task's probe found no matching key in the plugin's `:report --format json` payload (a stale key map or a dokku version that does not emit it). | +| `probe_rejected` | An older plugin rejected `:report --format json` outright, so the property task could not probe current state. | + +In every case `message` is masked, so a registered sensitive value that reaches the warning (for +example server stderr echoed by a rejected probe) renders as `***`. `--list-tasks --json` does not +emit a separate `warning` event; instead, the `list_task` event for a deprecated task carries +`"deprecated": true` and a `deprecation` field with the message. ## Commands diff --git a/tasks/dispatch.go b/tasks/dispatch.go index 1ccb585..ef7405f 100644 --- a/tasks/dispatch.go +++ b/tasks/dispatch.go @@ -91,7 +91,12 @@ func DispatchPlan(state State, funcMap map[State]func() PlanResult) PlanResult { // 3. otherwise - invoke p.apply (must be non-nil) and return its // TaskOutputState verbatim. apply is responsible for setting Changed // and a final State that matches DesiredState on success. -func ExecutePlan(p PlanResult) TaskOutputState { +func ExecutePlan(p PlanResult) (out TaskOutputState) { + // Probe diagnostics raised during planning ride out on every returned + // state so the apply run loop can drain them through the emitter, even on + // the error / in-sync branches that never invoke the apply closure. + defer func() { out.Warnings = append(out.Warnings, p.Warnings...) }() + if p.Error != nil { stdout, stderr, exitCode := p.Stdout, p.Stderr, p.ExitCode // Recover the underlying ExecCommandResponse if a probe helper @@ -131,7 +136,7 @@ func ExecutePlan(p PlanResult) TaskOutputState { State: p.DesiredState, } } - out := p.apply() + out = p.apply() if out.DesiredState == "" { out.DesiredState = p.DesiredState } diff --git a/tasks/dispatch_test.go b/tasks/dispatch_test.go index 03ed718..3ec2fca 100644 --- a/tasks/dispatch_test.go +++ b/tasks/dispatch_test.go @@ -107,6 +107,44 @@ func TestExecutePlanExplicitProbeFieldsTakePrecedence(t *testing.T) { } } +// TestExecutePlanCopiesWarnings pins that probe diagnostics on a PlanResult +// ride out on the returned TaskOutputState across every branch (error, in-sync, +// and apply), so the apply run loop can drain them through the emitter. (#353) +func TestExecutePlanCopiesWarnings(t *testing.T) { + warn := PlanWarning{Reason: WarnReasonUnknownProperty, Message: "no key foo"} + + assertWarned := func(label string, got TaskOutputState) { + t.Helper() + if len(got.Warnings) != 1 || got.Warnings[0] != warn { + t.Errorf("%s: warnings = %+v; want [%+v]", label, got.Warnings, warn) + } + } + + assertWarned("error branch", ExecutePlan(PlanResult{ + Status: PlanStatusError, + Error: errors.New("boom"), + DesiredState: StatePresent, + Warnings: []PlanWarning{warn}, + })) + + assertWarned("in-sync branch", ExecutePlan(PlanResult{ + InSync: true, + DesiredState: StatePresent, + Warnings: []PlanWarning{warn}, + })) + + // The apply closure returns a state with no warnings of its own; ExecutePlan + // appends the plan's warnings so the apply path still surfaces them. + assertWarned("apply branch", ExecutePlan(PlanResult{ + Status: PlanStatusModify, + DesiredState: StatePresent, + Warnings: []PlanWarning{warn}, + apply: func() TaskOutputState { + return TaskOutputState{Changed: true, State: StatePresent} + }, + })) +} + func TestWithExecResultZeroValueClears(t *testing.T) { // A no-op apply (no inputs) hands runExecInputs the zero // ExecCommandResponse; the contract is that the new fields then diff --git a/tasks/export.go b/tasks/export.go index 0286c8a..2ee7251 100644 --- a/tasks/export.go +++ b/tasks/export.go @@ -27,6 +27,15 @@ type GlobalExporter interface { ExportGlobal() ([]interface{}, error) } +// appExportReporter is an optional richer form of AppExporter: an exporter that +// can surface a non-fatal diagnostic (for example assets it could not capture) +// implements it so the warning reaches ExportReport.Warnings instead of a raw +// log line. exportAppPlay passes a warn callback wired to res.Report.Warnings +// and prefers this method when the task implements it. +type appExportReporter interface { + ExportAppReport(app string, warn func(msg string)) ([]interface{}, error) +} + // globalExportOrder is the fixed order in which not-app-scoped task types are // emitted into the leading global play. Adding a global resource means // implementing GlobalExporter on its task and adding its type-key here. @@ -286,7 +295,16 @@ func (res *ExportResult) exportAppPlay(app string, opts ExportOptions) map[strin if !ok { continue } - bodies, err := exporter.ExportApp(app) + var bodies []interface{} + var err error + if reporter, ok := proto.(appExportReporter); ok { + bodies, err = reporter.ExportAppReport(app, func(msg string) { + res.Report.Warnings = append(res.Report.Warnings, + fmt.Sprintf("%s: %s: %s", app, typeKey, msg)) + }) + } else { + bodies, err = exporter.ExportApp(app) + } if err != nil { res.Report.Warnings = append(res.Report.Warnings, fmt.Sprintf("%s: %s: %v", app, typeKey, err)) diff --git a/tasks/main.go b/tasks/main.go index 4d92640..f6536af 100644 --- a/tasks/main.go +++ b/tasks/main.go @@ -169,8 +169,35 @@ type TaskOutputState struct { // task executed. Empty when no subprocess ran. Same last-call-wins // rule as Stderr. Stdout string + + // Warnings carries non-fatal probe diagnostics discovered while planning + // (a property task's Plan() surfaces them, and ExecutePlan copies them off + // the PlanResult so the apply path can drain them). The run loop routes + // each entry through EventEmitter.TaskWarning; the message is masked at + // emit time. Empty for tasks that produced no diagnostic. + Warnings []PlanWarning +} + +// PlanWarning is a non-fatal probe diagnostic a task's Plan() surfaces for the +// run loop to route through EventEmitter.TaskWarning. Reason is a stable +// machine key (see the WarnReason* constants) so JSON consumers can branch on a +// typed category; Message is human-readable detail, stored raw and masked at +// emit time like PlanResult.Reason. +type PlanWarning struct { + Reason string + Message string } +const ( + // WarnReasonUnknownProperty marks a probe warning raised when a property's + // key is absent from the plugin's JSON report (a stale key map or a dokku + // version that does not emit it). + WarnReasonUnknownProperty = "unknown_property" + // WarnReasonProbeRejected marks a probe warning raised when an older plugin + // rejects `:report --format json` outright. + WarnReasonProbeRejected = "probe_rejected" +) + // WithExecResult returns a copy of s with Stdout/Stderr/ExitCode populated // from r. Callers use it from the success path so the returned state // mirrors the underlying subprocess.ExecCommandResponse without having to @@ -248,6 +275,13 @@ type PlanResult struct { Stderr string ExitCode int + // Warnings carries non-fatal probe diagnostics raised while planning (for + // example a property probe that found no matching report key). The run + // loop drains them through EventEmitter.TaskWarning; ExecutePlan copies + // them onto TaskOutputState so the apply path surfaces them too. Stored + // raw and masked at emit time, mirroring Reason. Empty when no diagnostic. + Warnings []PlanWarning + // apply, when non-nil, is the closure ExecutePlan invokes to mutate // server state. nil when InSync. Captures any probed state needed for // the mutation so the apply path does not re-probe. Unexported so diff --git a/tasks/maintenance_custom_page_task.go b/tasks/maintenance_custom_page_task.go index 37749f5..1734e96 100644 --- a/tasks/maintenance_custom_page_task.go +++ b/tasks/maintenance_custom_page_task.go @@ -9,7 +9,6 @@ import ( "errors" "fmt" "io" - "log" "os" "sort" "strings" @@ -345,7 +344,24 @@ func maintenanceCustomPageState(app string) (checksum string, reported bool, err return *report.CustomPageSHA256, true, nil } -// ExportApp emits a dokku_maintenance_custom_page task when the app has a custom +// ExportApp satisfies AppExporter by delegating to exportApp with a no-op warn +// callback. The export engine prefers ExportAppReport when present, so the +// dropped-assets diagnostic reaches ExportReport.Warnings rather than being +// discarded here. +func (t MaintenanceCustomPageTask) ExportApp(app string) ([]interface{}, error) { + return t.exportApp(app, func(string) {}) +} + +// ExportAppReport is the diagnostics-aware form of ExportApp (the +// appExportReporter interface): it routes the "dropped extra assets" warning +// through the engine's warn callback (wired to ExportReport.Warnings) instead +// of a raw log line, so the warning is rendered and masked like every other +// export diagnostic. +func (t MaintenanceCustomPageTask) ExportAppReport(app string, warn func(msg string)) ([]interface{}, error) { + return t.exportApp(app, warn) +} + +// exportApp emits a dokku_maintenance_custom_page task when the app has a custom // page installed. A custom page is detected by a non-empty custom-page-sha256 in // maintenance:report, so nothing is emitted when no page is set or when the // plugin is too old to report the checksum. The page content is then read back @@ -353,8 +369,10 @@ func maintenanceCustomPageState(app string) (checksum string, reported bool, err // self-contained task. On an older dokku-maintenance without the export command // (any non-SSH failure) the content cannot be read; an empty task is returned and // processMaintenanceCustomPage lifts the content into a required input. A -// transport-level SSH failure propagates as a warning. -func (t MaintenanceCustomPageTask) ExportApp(app string) ([]interface{}, error) { +// transport-level SSH failure propagates as a warning. When the archive carries +// files beyond maintenance.html (which the single-Content task cannot represent) +// warn is invoked with the dropped-assets notice. +func (t MaintenanceCustomPageTask) exportApp(app string, warn func(msg string)) ([]interface{}, error) { checksum, reported, err := maintenanceCustomPageState(app) if err != nil { var sshErr *subprocess.SSHError @@ -376,7 +394,7 @@ func (t MaintenanceCustomPageTask) ExportApp(app string) ([]interface{}, error) return []interface{}{MaintenanceCustomPageTask{App: app}}, nil } if extraAssets { - log.Printf("warning: dokku maintenance custom page for %q has files beyond maintenance.html; only maintenance.html is captured in the export", app) + warn("custom page has files beyond maintenance.html; only maintenance.html is captured in the export") } return []interface{}{MaintenanceCustomPageTask{App: app, Content: content}}, nil } diff --git a/tasks/maintenance_custom_page_task_test.go b/tasks/maintenance_custom_page_task_test.go index 5e51da8..d89732c 100644 --- a/tasks/maintenance_custom_page_task_test.go +++ b/tasks/maintenance_custom_page_task_test.go @@ -7,8 +7,76 @@ import ( "sort" "strings" "testing" + + "github.com/dokku/docket/subprocess" ) +// appExportReporter is satisfied by MaintenanceCustomPageTask so the export +// engine prefers ExportAppReport and routes the dropped-assets diagnostic into +// ExportReport.Warnings rather than a raw log line. #353. +var _ appExportReporter = MaintenanceCustomPageTask{} + +// TestMaintenanceCustomPageExportReportWarnsOnExtraAssets pins #353: when the +// exported archive carries files beyond maintenance.html, ExportAppReport routes +// the dropped-assets notice through the warn callback the engine wires to +// ExportReport.Warnings, and still captures the maintenance.html content. +func TestMaintenanceCustomPageExportReportWarnsOnExtraAssets(t *testing.T) { + tarball := tarFromEntries(t, map[string]string{ + "maintenance.html": maintenanceTestPage, + "assets/logo.png": "PNGDATA", + }) + defer subprocess.SetExecRunner(fakeDokku(map[string]string{ + "maintenance:report myapp --format json": `{"custom-page-sha256":"abc123"}`, + "--quiet maintenance:custom-page-export myapp": string(tarball), + }))() + + var warnings []string + bodies, err := MaintenanceCustomPageTask{}.ExportAppReport("myapp", func(msg string) { + warnings = append(warnings, msg) + }) + if err != nil { + t.Fatalf("ExportAppReport error: %v", err) + } + if len(warnings) != 1 { + t.Fatalf("expected 1 warning, got %d (%v)", len(warnings), warnings) + } + if !strings.Contains(warnings[0], "beyond maintenance.html") { + t.Errorf("warning = %q, want to mention the dropped assets", warnings[0]) + } + if len(bodies) != 1 { + t.Fatalf("expected 1 body, got %d", len(bodies)) + } + body, ok := bodies[0].(MaintenanceCustomPageTask) + if !ok { + t.Fatalf("body type = %T, want MaintenanceCustomPageTask", bodies[0]) + } + if body.Content != maintenanceTestPage { + t.Errorf("content = %q, want %q", body.Content, maintenanceTestPage) + } +} + +// TestMaintenanceCustomPageExportReportNoExtraAssets pins that a single +// maintenance.html produces no warning. +func TestMaintenanceCustomPageExportReportNoExtraAssets(t *testing.T) { + tarball := tarFromEntries(t, map[string]string{ + "maintenance.html": maintenanceTestPage, + }) + defer subprocess.SetExecRunner(fakeDokku(map[string]string{ + "maintenance:report myapp --format json": `{"custom-page-sha256":"abc123"}`, + "--quiet maintenance:custom-page-export myapp": string(tarball), + }))() + + var warnings []string + if _, err := (MaintenanceCustomPageTask{}).ExportAppReport("myapp", func(msg string) { + warnings = append(warnings, msg) + }); err != nil { + t.Fatalf("ExportAppReport error: %v", err) + } + if len(warnings) != 0 { + t.Errorf("expected no warnings, got %v", warnings) + } +} + // tarFromEntries builds an uncompressed tar archive from name->body pairs for // use in the checksum tests. func tarFromEntries(t *testing.T, entries map[string]string) []byte { diff --git a/tasks/properties.go b/tasks/properties.go index 7ba06b0..731f127 100644 --- a/tasks/properties.go +++ b/tasks/properties.go @@ -4,7 +4,6 @@ import ( "encoding/json" "errors" "fmt" - "log" "sort" "strings" @@ -220,15 +219,16 @@ func getPropertyArgs(plugin, app string, global bool) []string { return append(args, "--format", "json") } -// warnIfUnknownProperty surfaces a diagnostic when the probe identifies the -// property as unknown, either because the JSON payload had no matching key -// (likely a stale map or a dokku version mismatch) or because the :report -// invocation rejected `--format json` itself (older plugin versions). Other -// errors are silent because callers already propagate them through -// PlanResult.Reason. -func warnIfUnknownProperty(plugin, property string, err error) { +// unknownPropertyWarning returns a diagnostic (and true) when the probe +// identifies the property as unknown, either because the JSON payload had no +// matching key (likely a stale map or a dokku version mismatch) or because the +// :report invocation rejected `--format json` itself (older plugin versions). +// It returns ok=false for every other error, since callers already propagate +// those through PlanResult.Reason. The returned message is raw; planProperty +// attaches it to PlanResult.Warnings and the emitter masks it at output time. +func unknownPropertyWarning(plugin, property string, err error) (PlanWarning, bool) { if err == nil { - return + return PlanWarning{}, false } var unknown *errUnknownProperty @@ -237,23 +237,27 @@ func warnIfUnknownProperty(plugin, property string, err error) { // letsencrypt dns-provider-*) where missing-from-report is the // normal pre-set state, not a typo. if isDynamicProperty(plugin, property) { - return + return PlanWarning{}, false } - log.Printf("warning: dokku %s:report has no key %q for property %q (available keys: %s)", - plugin, unknown.lookedFor, property, - strings.Join(unknown.validKeys, ", ")) - return + return PlanWarning{ + Reason: WarnReasonUnknownProperty, + Message: fmt.Sprintf("dokku %s:report has no key %q for property %q (available keys: %s)", + plugin, unknown.lookedFor, property, strings.Join(unknown.validKeys, ", ")), + }, true } var execErr *subprocess.ExecError if !errors.As(err, &execErr) { - return + return PlanWarning{}, false } stderr := strings.TrimSpace(execErr.Response.Stderr) if !strings.Contains(stderr, "Invalid flag passed, valid flags:") { - return + return PlanWarning{}, false } - log.Printf("warning: dokku %s:report rejected probe for property %q: %s", plugin, property, stderr) + return PlanWarning{ + Reason: WarnReasonProbeRejected, + Message: fmt.Sprintf("dokku %s:report rejected probe for property %q: %s", plugin, property, stderr), + }, true } // isDynamicProperty reports whether a (plugin, property) pair represents a @@ -282,9 +286,10 @@ func isDynamicProperty(plugin, property string) bool { // // When the probe errors (other than SSH transport failures), the apply // closure runs the set/unset unconditionally. Diagnostic warnings are -// emitted via warnIfUnknownProperty for typos and unsupported plugin -// versions; other probe failures are recorded in PlanResult.Reason and -// the apply still runs, matching pre-probe behavior. +// attached to PlanResult.Warnings via unknownPropertyWarning for typos and +// unsupported plugin versions (the run loop routes them through the emitter); +// other probe failures are recorded in PlanResult.Reason and the apply still +// runs, matching pre-probe behavior. // validatePropertyInput checks a property task's inputs without probing the // server: app/global scoping, that the property is supported for the target // scope, and that a value is supplied only in the state that allows it. Both @@ -345,12 +350,15 @@ func planProperty(state State, app string, global bool, property, value, subcomm if sensitive { subprocess.AddGlobalSensitive(current) } + var warnings []PlanWarning if probeErr != nil { var sshErr *subprocess.SSHError if errors.As(probeErr, &sshErr) { return PlanResult{Status: PlanStatusError, Error: probeErr} } - warnIfUnknownProperty(plugin, property, probeErr) + if w, ok := unknownPropertyWarning(plugin, property, probeErr); ok { + warnings = append(warnings, w) + } } if probeErr == nil && current == value { return PlanResult{InSync: true, Status: PlanStatusOK} @@ -374,6 +382,7 @@ func planProperty(state State, app string, global bool, property, value, subcomm Reason: reason, Mutations: []string{fmt.Sprintf("set %s=%s", property, value)}, Commands: resolveCommands(inputs), + Warnings: warnings, apply: applyPropertySet(subcommand, target, property, value), } }, @@ -386,12 +395,15 @@ func planProperty(state State, app string, global bool, property, value, subcomm if sensitive { subprocess.AddGlobalSensitive(current) } + var warnings []PlanWarning if probeErr != nil { var sshErr *subprocess.SSHError if errors.As(probeErr, &sshErr) { return PlanResult{Status: PlanStatusError, Error: probeErr} } - warnIfUnknownProperty(plugin, property, probeErr) + if w, ok := unknownPropertyWarning(plugin, property, probeErr); ok { + warnings = append(warnings, w) + } } if probeErr == nil && current == "" { return PlanResult{InSync: true, Status: PlanStatusOK} @@ -411,6 +423,7 @@ func planProperty(state State, app string, global bool, property, value, subcomm Reason: reason, Mutations: []string{fmt.Sprintf("unset %s", property)}, Commands: resolveCommands(inputs), + Warnings: warnings, apply: applyPropertyUnset(subcommand, target, property), } }, diff --git a/tasks/properties_test.go b/tasks/properties_test.go index dc16762..2623f64 100644 --- a/tasks/properties_test.go +++ b/tasks/properties_test.go @@ -1,10 +1,8 @@ package tasks import ( - "bytes" "context" "errors" - "log" "reflect" "strings" "testing" @@ -169,103 +167,152 @@ func TestReadPropertyReportInstalledExecFailureErrors(t *testing.T) { } } -func captureLog(t *testing.T) *bytes.Buffer { - t.Helper() - buf := &bytes.Buffer{} - orig := log.Writer() - flags := log.Flags() - prefix := log.Prefix() - log.SetOutput(buf) - log.SetFlags(0) - log.SetPrefix("") - t.Cleanup(func() { - log.SetOutput(orig) - log.SetFlags(flags) - log.SetPrefix(prefix) - }) - return buf -} - -func TestWarnIfUnknownPropertyMissingKey(t *testing.T) { - buf := captureLog(t) +func TestUnknownPropertyWarningMissingKey(t *testing.T) { err := &errUnknownProperty{ plugin: "nginx", property: "selecte", lookedFor: "selecte", validKeys: []string{"bind-address-ipv4", "selected"}, } - warnIfUnknownProperty("nginx", "selecte", err) - out := buf.String() - if !strings.Contains(out, "no key") { - t.Errorf("log output missing 'no key': %q", out) - } - if !strings.Contains(out, "nginx") { - t.Errorf("log output missing plugin name: %q", out) + w, ok := unknownPropertyWarning("nginx", "selecte", err) + if !ok { + t.Fatal("expected a warning for a missing report key") } - if !strings.Contains(out, "selecte") { - t.Errorf("log output missing property name: %q", out) + if w.Reason != WarnReasonUnknownProperty { + t.Errorf("reason = %q; want %q", w.Reason, WarnReasonUnknownProperty) } - if !strings.Contains(out, "selected") { - t.Errorf("log output missing available key list: %q", out) + for _, want := range []string{"no key", "nginx", "selecte", "selected"} { + if !strings.Contains(w.Message, want) { + t.Errorf("message %q missing %q", w.Message, want) + } } } -func TestWarnIfUnknownPropertyInvalidFlag(t *testing.T) { - buf := captureLog(t) +func TestUnknownPropertyWarningInvalidFlag(t *testing.T) { execErr := &subprocess.ExecError{ Response: subprocess.ExecCommandResponse{ Stderr: "Invalid flag passed, valid flags: --letsencrypt-email", }, Err: errors.New("exit status 1"), } - warnIfUnknownProperty("letsencrypt", "email", execErr) - out := buf.String() - if !strings.Contains(out, "rejected probe") { - t.Errorf("log output missing 'rejected probe': %q", out) + w, ok := unknownPropertyWarning("letsencrypt", "email", execErr) + if !ok { + t.Fatal("expected a warning for a rejected probe") } - if !strings.Contains(out, "letsencrypt") { - t.Errorf("log output missing plugin name: %q", out) + if w.Reason != WarnReasonProbeRejected { + t.Errorf("reason = %q; want %q", w.Reason, WarnReasonProbeRejected) } - if !strings.Contains(out, "Invalid flag passed") { - t.Errorf("log output missing stderr snippet: %q", out) + for _, want := range []string{"rejected probe", "letsencrypt", "Invalid flag passed"} { + if !strings.Contains(w.Message, want) { + t.Errorf("message %q missing %q", w.Message, want) + } } } -func TestWarnIfUnknownPropertyIgnoresOtherErrors(t *testing.T) { - buf := captureLog(t) - warnIfUnknownProperty("nginx", "bind-address-ipv4", nil) - if buf.Len() != 0 { - t.Errorf("log output should be empty for nil error, got %q", buf.String()) - } +// TestUnknownPropertyWarningMasksSensitiveStderr is the core #353 guarantee: +// the rejected-probe branch embeds the server's raw stderr, and a registered +// secret that reaches it must mask at emit time. The message is stored raw +// (like PlanResult.Reason) so the assertion masks it the way the emitter does. +func TestUnknownPropertyWarningMasksSensitiveStderr(t *testing.T) { + subprocess.SetGlobalSensitive(nil) + t.Cleanup(func() { subprocess.SetGlobalSensitive(nil) }) + subprocess.AddGlobalSensitive("s3cr3t") - warnIfUnknownProperty("nginx", "bind-address-ipv4", errors.New("plain")) - if buf.Len() != 0 { - t.Errorf("log output should be empty for plain error, got %q", buf.String()) + execErr := &subprocess.ExecError{ + Response: subprocess.ExecCommandResponse{ + Stderr: "Invalid flag passed, valid flags: --token near value s3cr3t", + }, + Err: errors.New("exit status 1"), + } + w, ok := unknownPropertyWarning("registry", "password", execErr) + if !ok { + t.Fatal("expected a warning for a rejected probe") + } + if !strings.Contains(w.Message, "s3cr3t") { + t.Fatalf("message should embed raw stderr pre-masking, got %q", w.Message) } + if masked := subprocess.MaskString(w.Message); strings.Contains(masked, "s3cr3t") { + t.Errorf("masked warning leaked secret: %q -> %q", w.Message, masked) + } +} +func TestUnknownPropertyWarningIgnoresOtherErrors(t *testing.T) { + if _, ok := unknownPropertyWarning("nginx", "bind-address-ipv4", nil); ok { + t.Error("nil error should not warn") + } + if _, ok := unknownPropertyWarning("nginx", "bind-address-ipv4", errors.New("plain")); ok { + t.Error("plain error should not warn") + } execErr := &subprocess.ExecError{ Response: subprocess.ExecCommandResponse{ Stderr: "App nonexistent does not exist", }, Err: errors.New("exit status 1"), } - warnIfUnknownProperty("nginx", "bind-address-ipv4", execErr) - if buf.Len() != 0 { - t.Errorf("log output should be empty for non-flag exec error, got %q", buf.String()) + if _, ok := unknownPropertyWarning("nginx", "bind-address-ipv4", execErr); ok { + t.Error("non-flag exec error should not warn") } } -func TestWarnIfUnknownPropertyDynamicPropertySkipsWarning(t *testing.T) { - buf := captureLog(t) +func TestUnknownPropertyWarningDynamicPropertySkipsWarning(t *testing.T) { err := &errUnknownProperty{ plugin: "letsencrypt", property: "dns-provider-NAMECHEAP_API_USER", lookedFor: "dns-provider-NAMECHEAP_API_USER", validKeys: []string{"email", "server"}, } - warnIfUnknownProperty("letsencrypt", "dns-provider-NAMECHEAP_API_USER", err) - if buf.Len() != 0 { - t.Errorf("log output should be empty for dynamic property, got %q", buf.String()) + if _, ok := unknownPropertyWarning("letsencrypt", "dns-provider-NAMECHEAP_API_USER", err); ok { + t.Error("dynamic property should not warn") + } +} + +// TestPlanPropertyAttachesUnknownKeyWarning drives the whole Plan() path: a +// report payload missing the probed key yields drift plus a PlanWarning the run +// loop can drain. (#353) +func TestPlanPropertyAttachesUnknownKeyWarning(t *testing.T) { + keys := map[string]PropertyKeys{ + "hsts": {PerApp: "hsts", Global: ""}, + } + defer subprocess.SetExecRunner(fakeDokku(map[string]string{ + "--quiet nginx:report myapp --format json": `{"proxy-read-timeout":"60s"}`, + }))() + + res := planProperty(StatePresent, "myapp", false, "hsts", "true", "nginx:set", keys) + if res.Error != nil { + t.Fatalf("planProperty error: %v", res.Error) + } + if len(res.Warnings) != 1 { + t.Fatalf("expected 1 warning, got %d (%v)", len(res.Warnings), res.Warnings) + } + if res.Warnings[0].Reason != WarnReasonUnknownProperty { + t.Errorf("reason = %q; want %q", res.Warnings[0].Reason, WarnReasonUnknownProperty) + } +} + +// TestPlanPropertyAttachesRejectedProbeWarning drives the older-plugin path: +// `:report --format json` fails with an "Invalid flag" stderr, so the probe +// error becomes drift plus a probe_rejected PlanWarning. (#353) +func TestPlanPropertyAttachesRejectedProbeWarning(t *testing.T) { + keys := map[string]PropertyKeys{ + "hsts": {PerApp: "hsts", Global: ""}, + } + defer subprocess.SetExecRunner(func(_ context.Context, in subprocess.ExecCommandInput) (subprocess.ExecCommandResponse, error) { + resp := subprocess.ExecCommandResponse{ + Stderr: "Invalid flag passed, valid flags: --app, --global", + ExitCode: 1, + } + return resp, &subprocess.ExecError{Response: resp, Err: errors.New("exit status 1"), Ran: true} + })() + + res := planProperty(StatePresent, "myapp", false, "hsts", "true", "nginx:set", keys) + if res.Error != nil { + t.Fatalf("planProperty error: %v", res.Error) + } + if len(res.Warnings) != 1 { + t.Fatalf("expected 1 warning, got %d (%v)", len(res.Warnings), res.Warnings) + } + if res.Warnings[0].Reason != WarnReasonProbeRejected { + t.Errorf("reason = %q; want %q", res.Warnings[0].Reason, WarnReasonProbeRejected) } }