Skip to content

Commit 2f54909

Browse files
authored
fix(audit): record what ran — plus the outstanding follow-ups (#215)
1 parent c8aeb6b commit 2f54909

15 files changed

Lines changed: 621 additions & 45 deletions

File tree

cmd/exec.go

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -107,15 +107,14 @@ func runExec(cmd *cobra.Command, args []string) error {
107107
os.Stdout.Write(out)
108108
if execErr != nil {
109109
writeAudit(auditEvent{Command: "exec", Node: nodeName, Target: nc.Target.String(),
110-
Result: "error", ErrorCode: "EXEC_ERROR", Start: start})
110+
Result: "error", ErrorCode: "EXEC_ERROR", Detail: bin, Start: start})
111111
return output.NewError("EXEC_ERROR", output.ExitGeneralError,
112112
fmt.Sprintf("exec on %s failed: %v", nodeName, execErr))
113113
}
114-
// Audited like every other verb that touches a node. The entry records
115-
// that an exec happened, not what ran: AuditEntry has no field for it,
116-
// and the argv is the one place a caller is most likely to have put a
117-
// token or key. Recording the program name would need a schema change.
114+
// Detail is the program only. The rest of the argv is where a caller
115+
// is most likely to have put a token, and an audit log is the wrong
116+
// place to learn one.
118117
writeAudit(auditEvent{Command: "exec", Node: nodeName, Target: nc.Target.String(),
119-
Result: "success", Start: start})
118+
Result: "success", Detail: bin, Start: start})
120119
return nil
121120
}

cmd/files.go

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,7 @@ func runFilesPut(cmd *cobra.Command, args []string) error {
8989
// Direct host write via Target.WriteFile.
9090
if err := nc.Target.WriteFile(ctx, remoteDst, data, 0o644); err != nil {
9191
writeAudit(auditEvent{Command: "files put", Node: nodeName, Target: nc.Target.String(),
92-
Result: "error", ErrorCode: "FILES_ERROR", Start: start})
92+
Result: "error", ErrorCode: "FILES_ERROR", Detail: remoteDst, Start: start})
9393
return output.NewError("FILES_ERROR", output.ExitGeneralError,
9494
fmt.Sprintf("write to %s: %v", remoteDst, err))
9595
}
@@ -115,23 +115,28 @@ func runFilesPut(cmd *cobra.Command, args []string) error {
115115

116116
if _, err := nc.Target.Exec(ctx, "docker", "cp", stagePath, fmt.Sprintf("%s:%s", nodeName, remoteDst)); err != nil {
117117
writeAudit(auditEvent{Command: "files put", Node: nodeName, Target: nc.Target.String(),
118-
Result: "error", ErrorCode: "FILES_ERROR", Start: start})
118+
Result: "error", ErrorCode: "FILES_ERROR", Detail: remoteDst, Start: start})
119119
return output.NewError("FILES_ERROR", output.ExitGeneralError,
120120
fmt.Sprintf("docker cp into %s: %v", nodeName, err))
121121
}
122122
}
123123

124-
// Audited like the other verbs that change a node. Records that bytes
125-
// were written and where, not their contents.
124+
// Records where the bytes went, never what they were.
126125
writeAudit(auditEvent{Command: "files put", Node: nodeName, Target: nc.Target.String(),
127-
Result: "success", Start: start})
126+
Result: "success", Detail: remoteDst, Start: start})
128127
return writeFilesResult(outputFmt, "put", nodeName, localSrc, remoteDst, len(data))
129128
}
130129

131130
func runFilesGet(cmd *cobra.Command, args []string) error {
132131
nodeName, remoteSrc, localDst := args[0], args[1], args[2]
133132
outputFmt, _ := cmd.Flags().GetString("output")
134133

134+
// get reads an arbitrary path off the node. That is not a mutation, so
135+
// it is not gated — but a jar node's config.conf carries the
136+
// block-signing key in localwitness, so which path was read is worth
137+
// recording even when reading it was entirely legitimate.
138+
start := time.Now()
139+
135140
nc, err := resolveNodeContext(nodeName)
136141
if err != nil {
137142
return err
@@ -178,6 +183,8 @@ func runFilesGet(cmd *cobra.Command, args []string) error {
178183
return output.NewError("FILES_ERROR", output.ExitGeneralError, err.Error())
179184
}
180185

186+
writeAudit(auditEvent{Command: "files get", Node: nodeName, Target: nc.Target.String(),
187+
Result: "success", Detail: remoteSrc, Start: start})
181188
return writeFilesResult(outputFmt, "get", nodeName, remoteSrc, localDst, len(data))
182189
}
183190

cmd/recipe.go

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,12 @@
11
package cmd
22

33
import (
4+
"crypto/rand"
5+
"encoding/hex"
46
"fmt"
57
"os"
68
"strings"
9+
"time"
710

811
"github.com/spf13/cobra"
912

@@ -243,6 +246,15 @@ func runRecipeRun(cmd *cobra.Command, args []string) error {
243246
if err != nil {
244247
exe = os.Args[0]
245248
}
249+
runStart := time.Now()
250+
// One id per run, minted here and inherited by every step's child
251+
// process. Random rather than sequential: two runs against the same
252+
// state dir must not collide, and a counter would need state of its
253+
// own.
254+
runID, err := newAuditRunID()
255+
if err != nil {
256+
return output.NewError("INTERNAL_ERROR", output.ExitGeneralError, err.Error())
257+
}
246258

247259
// Dry-run prints its plan to Out. In json mode that is the same stream
248260
// the RunResult goes to, so the plan lines land in front of the JSON
@@ -267,8 +279,46 @@ func runRecipeRun(cmd *cobra.Command, args []string) error {
267279
StateDir: paths.BaseDir(),
268280
RequirePrivate: guard.Requested(),
269281
AllowHostExec: recipeAllowHostExec,
282+
RunID: runID,
283+
RunIDEnv: AuditRunIDEnv,
284+
// Host steps never re-enter trond, so nothing else would record
285+
// them. Detail names the step and its program — an identifier,
286+
// not the argv or the script body.
287+
AuditHostStep: func(step recipe.Step, sr recipe.StepResult) {
288+
result, code := "success", ""
289+
if sr.Error != "" {
290+
result, code = "error", "HOST_STEP_ERROR"
291+
}
292+
writeAudit(auditEvent{
293+
RunID: runID,
294+
Command: "recipe host-step",
295+
Result: result,
296+
ErrorCode: code,
297+
Detail: step.ID + ": " + hostStepProgram(step),
298+
Start: time.Now().Add(-time.Duration(sr.DurationMs) * time.Millisecond),
299+
})
300+
},
270301
})
271302

303+
// One entry for the run itself, whatever its steps did. Without it a
304+
// recipe — the most capable single command trond has, now that a step
305+
// can be an arbitrary host program — is the only thing that can act
306+
// and leave nothing behind.
307+
if res != nil {
308+
result, code := "success", ""
309+
if runErr != nil {
310+
result, code = "error", "RECIPE_FAILED"
311+
}
312+
writeAudit(auditEvent{
313+
RunID: runID,
314+
Command: "recipe run",
315+
Result: result,
316+
ErrorCode: code,
317+
Detail: source,
318+
Start: runStart,
319+
})
320+
}
321+
272322
if res != nil {
273323
res.Source = source
274324
}
@@ -296,6 +346,25 @@ func runRecipeRun(cmd *cobra.Command, args []string) error {
296346
return nil
297347
}
298348

349+
// newAuditRunID mints a short random correlation id.
350+
func newAuditRunID() (string, error) {
351+
var b [8]byte
352+
if _, err := rand.Read(b[:]); err != nil {
353+
return "", fmt.Errorf("generate audit run id: %w", err)
354+
}
355+
return hex.EncodeToString(b[:]), nil
356+
}
357+
358+
// hostStepProgram names what a host step executes, for the audit detail:
359+
// the program for a run: step, "sh" for a script: step. Never the
360+
// arguments or the script body — those are payload.
361+
func hostStepProgram(step recipe.Step) string {
362+
if len(step.Run) > 0 {
363+
return step.Run[0]
364+
}
365+
return "sh"
366+
}
367+
299368
func parseParamFlags(pairs []string) (map[string]string, error) {
300369
out := map[string]string{}
301370
for _, p := range pairs {

cmd/recipe_audit_test.go

Lines changed: 165 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,165 @@
1+
package cmd
2+
3+
import (
4+
"encoding/json"
5+
"os"
6+
"path/filepath"
7+
"strings"
8+
"testing"
9+
10+
"github.com/tronprotocol/tron-deployment/internal/paths"
11+
)
12+
13+
// A recipe run is the most capable single command trond has — since
14+
// `kind: host`, one step can be an arbitrary program — and it was the
15+
// only one that could act and leave nothing in the audit log. Command
16+
// steps re-exec trond, so the child writes its own entry; host steps
17+
// never re-enter trond, and the run itself was never recorded at all.
18+
19+
func writeTempRecipe(t *testing.T, body string) string {
20+
t.Helper()
21+
p := filepath.Join(t.TempDir(), "r.yaml")
22+
if err := os.WriteFile(p, []byte(body), 0o600); err != nil {
23+
t.Fatalf("write recipe: %v", err)
24+
}
25+
return p
26+
}
27+
28+
// auditLines returns (command, detail, result) for each audit entry.
29+
func auditLines(t *testing.T) [][3]string {
30+
t.Helper()
31+
raw, err := os.ReadFile(paths.AuditLog())
32+
if err != nil {
33+
if os.IsNotExist(err) {
34+
return nil
35+
}
36+
t.Fatalf("read audit log: %v", err)
37+
}
38+
var out [][3]string
39+
for _, line := range strings.Split(strings.TrimSpace(string(raw)), "\n") {
40+
if line == "" {
41+
continue
42+
}
43+
var e struct{ Command, Detail, Result string }
44+
if err := json.Unmarshal([]byte(line), &e); err != nil {
45+
t.Fatalf("audit line %q: %v", line, err)
46+
}
47+
out = append(out, [3]string{e.Command, e.Detail, e.Result})
48+
}
49+
return out
50+
}
51+
52+
func setupRecipeAudit(t *testing.T) {
53+
t.Helper()
54+
paths.SetBaseDir(t.TempDir())
55+
t.Cleanup(func() { paths.SetBaseDir("") })
56+
t.Cleanup(func() {
57+
recipeFile, recipeAllowHostExec, recipeRunDryRun = "", false, false
58+
recipeRunParams = nil
59+
})
60+
}
61+
62+
func TestRecipeRun_AuditsRunAndHostSteps(t *testing.T) {
63+
setupRecipeAudit(t)
64+
marker := filepath.Join(t.TempDir(), "ran")
65+
recipeFile = writeTempRecipe(t, `name: audited
66+
steps:
67+
- id: stage
68+
kind: host
69+
run: ["touch", "`+marker+`"]
70+
`)
71+
recipeAllowHostExec = true
72+
73+
if err := runRecipeRun(newCmd(), nil); err != nil {
74+
t.Fatalf("runRecipeRun: %v", err)
75+
}
76+
77+
lines := auditLines(t)
78+
var host, run [3]string
79+
for _, l := range lines {
80+
switch l[0] {
81+
case "recipe host-step":
82+
host = l
83+
case "recipe run":
84+
run = l
85+
}
86+
}
87+
if host[0] == "" {
88+
t.Fatalf("no `recipe host-step` entry; a host step ran and the log never saw it.\ngot: %v", lines)
89+
}
90+
if !strings.Contains(host[1], "stage") || !strings.Contains(host[1], "touch") {
91+
t.Errorf("host-step detail = %q, want it to name the step and its program", host[1])
92+
}
93+
if run[0] == "" {
94+
t.Fatalf("no `recipe run` entry.\ngot: %v", lines)
95+
}
96+
if run[1] != recipeFile {
97+
t.Errorf("run detail = %q, want the recipe source %q", run[1], recipeFile)
98+
}
99+
if run[2] != "success" {
100+
t.Errorf("run result = %q, want success", run[2])
101+
}
102+
}
103+
104+
// TestRecipeRun_RefusedHostStepLeavesNoStepEntry: the audit log records
105+
// what ran. A step refused by --allow-host-exec did not run, so claiming
106+
// it did would be worse than silence — but the run itself is still
107+
// recorded, as a failure.
108+
func TestRecipeRun_RefusedHostStepLeavesNoStepEntry(t *testing.T) {
109+
setupRecipeAudit(t)
110+
marker := filepath.Join(t.TempDir(), "ran")
111+
recipeFile = writeTempRecipe(t, `name: refused
112+
steps:
113+
- id: stage
114+
kind: host
115+
run: ["touch", "`+marker+`"]
116+
`)
117+
// recipeAllowHostExec stays false.
118+
119+
if err := runRecipeRun(newCmd(), nil); err == nil {
120+
t.Fatal("want the refusal to surface as an error")
121+
}
122+
if _, err := os.Stat(marker); err == nil {
123+
t.Fatal("the refused step ran")
124+
}
125+
126+
for _, l := range auditLines(t) {
127+
if l[0] == "recipe host-step" {
128+
t.Errorf("audited a host step that never ran: %v", l)
129+
}
130+
}
131+
var found bool
132+
for _, l := range auditLines(t) {
133+
if l[0] == "recipe run" {
134+
found = true
135+
if l[2] != "error" {
136+
t.Errorf("run result = %q, want error", l[2])
137+
}
138+
}
139+
}
140+
if !found {
141+
t.Error("a failed run left no `recipe run` entry")
142+
}
143+
}
144+
145+
// TestRecipeRun_DryRunAuditsNoHostStep — a preview executed nothing.
146+
func TestRecipeRun_DryRunAuditsNoHostStep(t *testing.T) {
147+
setupRecipeAudit(t)
148+
recipeFile = writeTempRecipe(t, `name: preview
149+
steps:
150+
- id: stage
151+
kind: host
152+
run: ["touch", "/tmp/should-not-happen"]
153+
`)
154+
recipeAllowHostExec = true
155+
recipeRunDryRun = true
156+
157+
if err := runRecipeRun(newCmd(), nil); err != nil {
158+
t.Fatalf("dry-run: %v", err)
159+
}
160+
for _, l := range auditLines(t) {
161+
if l[0] == "recipe host-step" {
162+
t.Errorf("dry-run audited a host step: %v", l)
163+
}
164+
}
165+
}

cmd/resolve.go

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,10 @@
11
package cmd
22

33
import (
4+
"cmp"
45
"context"
56
"fmt"
7+
"os"
68
"time"
79

810
"github.com/tronprotocol/tron-deployment/internal/guard"
@@ -176,9 +178,17 @@ type auditEvent struct {
176178
IntentHash string
177179
Result string // "success", "error", "rollback"
178180
ErrorCode string
181+
Detail string // what was acted on; identifiers only, never payloads
182+
RunID string // set by the process that mints the id; children inherit it via the environment
179183
Start time.Time
180184
}
181185

186+
// AuditRunIDEnv carries a recipe run's correlation id into the steps it
187+
// re-execs. Read from the environment rather than passed as a flag: every
188+
// trond command writes audit entries, and threading a parameter through
189+
// all of them to serve one caller is the wrong shape.
190+
const AuditRunIDEnv = "TROND_AUDIT_RUN_ID"
191+
182192
// writeAudit writes an audit log entry for a mutating command. Failures are
183193
// logged but never propagated — losing an audit line should not break the
184194
// command that triggered it.
@@ -197,6 +207,8 @@ func writeAudit(ev auditEvent) {
197207
Result: ev.Result,
198208
DurationMs: time.Since(ev.Start).Milliseconds(),
199209
ErrorCode: ev.ErrorCode,
210+
Detail: ev.Detail,
211+
RunID: cmp.Or(ev.RunID, os.Getenv(AuditRunIDEnv)),
200212
}
201213
if writeErr := al.Write(entry); writeErr != nil {
202214
Log().Warn("audit log write failed", "error", writeErr)

0 commit comments

Comments
 (0)