Audit what an exec's command did

docs/api/swagger.json

@@ -1410,7 +1410,7 @@
                         "BearerAuth": []
                     }
                 ],
-                "description": "Runs `argv` inside the jail as root and returns its stdout, stderr and\nexit code. This is JD-007's \"hand off to in-jail provisioning\" made\ncallable, and it is root in the jail — no more than this API already\nimplies (JD-001, JD-016).\n\n**A non-zero exit is still a `200`.** The exec succeeded; the thing it ran\nfailed, and `exit_code` is the answer. A client that reads the HTTP status\ninstead is reading the wrong field. `exit_code` is `-1` when the command\nnever ran or was stopped by the timeout.\n\n**`argv` is an array and there is no shell.** Nothing splits a string here,\nso a quote or a semicolon in an argument is just a character. A caller who\nwants a shell asks for one — `[\"sh\", \"-c\", \"…\"]` — and has chosen it. There\nis no stdin: a command that needs input writes a file in the jail first.\n\n**The environment is clean.** The command runs under `jexec -l`, which gives\nit `HOME`, `PATH`, `SHELL`, `USER` and `LANG` and nothing of the host's —\nmeasured, plain `jexec` hands the jail everything the Jail Deck process was\nstarted with, `jaildeck.env` included. `env` adds variables on top of that.\n\nA request that sets `env` and whose `argv[0]` contains an `=` is refused:\n`env(1)` has no way to end its assignments — measured, `env -- cmd` fails —\nso it would read that argument as one more and run nothing.\n\n**`timeout`** is a duration like `\"30s\"` or `\"2m\"`, 60s by default and five\nminutes at most (JD-014). Longer is refused rather than clamped, because a\ncommand silently given less time than asked for looks like one that failed.\nWork that needs longer belongs in a template, which is prepared in the\nbackground and polled (JD-008). A timed-out command is **killed inside the\njail**, along with anything it forked, and whatever it printed first is\nstill returned with `timed_out: true`.\n\nEach stream is capped at 1 MiB and says so with `stdout_truncated` /\n`stderr_truncated` — output that stops exactly at the cap is otherwise\nindistinguishable from output that happened to end there.\n\nEvery call is audited with the command line it became, which includes any\nenvironment values: a secret passed this way is written to the audit log,\nwhich is `0700` and root-owned for that kind of reason.",
+                "description": "Runs `argv` inside the jail as root and returns its stdout, stderr and\nexit code. This is JD-007's \"hand off to in-jail provisioning\" made\ncallable, and it is root in the jail — no more than this API already\nimplies (JD-001, JD-016).\n\n**A non-zero exit is still a `200`.** The exec succeeded; the thing it ran\nfailed, and `exit_code` is the answer. A client that reads the HTTP status\ninstead is reading the wrong field. `exit_code` is `-1` when the command\nnever ran or was stopped by the timeout.\n\n**`argv` is an array and there is no shell.** Nothing splits a string here,\nso a quote or a semicolon in an argument is just a character. A caller who\nwants a shell asks for one — `[\"sh\", \"-c\", \"…\"]` — and has chosen it. There\nis no stdin: a command that needs input writes a file in the jail first.\n\n**The environment is clean.** The command runs under `jexec -l`, which gives\nit `HOME`, `PATH`, `SHELL`, `USER` and `LANG` and nothing of the host's —\nmeasured, plain `jexec` hands the jail everything the Jail Deck process was\nstarted with, `jaildeck.env` included. `env` adds variables on top of that.\n\nA request that sets `env` and whose `argv[0]` contains an `=` is refused:\n`env(1)` has no way to end its assignments — measured, `env -- cmd` fails —\nso it would read that argument as one more and run nothing.\n\n**`timeout`** is a duration like `\"30s\"` or `\"2m\"`, 60s by default and five\nminutes at most (JD-014). Longer is refused rather than clamped, because a\ncommand silently given less time than asked for looks like one that failed.\nWork that needs longer belongs in a template, which is prepared in the\nbackground and polled (JD-008). A timed-out command is **killed inside the\njail**, along with anything it forked, and whatever it printed first is\nstill returned with `timed_out: true`.\n\nEach stream is capped at 1 MiB and says so with `stdout_truncated` /\n`stderr_truncated` — output that stops exactly at the cap is otherwise\nindistinguishable from output that happened to end there.\n\nEvery call is audited with the command line it became, which includes any\nenvironment values: a secret passed this way is written to the audit log,\nwhich is `0700` and root-owned for that kind of reason. A command that ran is\na successful entry whatever it exited with, and the entry carries what came of\nit: its `exit_code`, `timed_out`, and `duration_ms`.",
                 "consumes": [
                     "application/json"
                 ],
@@ -3323,7 +3323,7 @@
                     "type": "string"
                 },
                 "principal": {
-                    "description": "The three a session carries, which a command does not (JD-042): who\nopened it (\"session\", or \"token:\u003cname\u003e\"), how long it lasted, and why it\nended. Omitted on every other entry.",
+                    "description": "Who opened a console session (\"session\", or \"token:\u003cname\u003e\"), how long\nit lasted, and why it ended (JD-042). DurationMS is also an exec's, how\nlong the command ran (#141). Omitted on every other entry.",
                     "type": "string"
                 },
                 "reason": {

internal/audit/logger.go

@@ -18,9 +18,9 @@ type Entry struct {
 	// (JD-011: nothing is stored that the request did not supply).
 	RequestID string `json:"request_id,omitempty"`
 
-	// The three a session carries, which a command does not (JD-042): who
-	// opened it ("session", or "token:<name>"), how long it lasted, and why it
-	// ended. Omitted on every other entry.
+	// Who opened a console session ("session", or "token:<name>"), how long
+	// it lasted, and why it ended (JD-042). DurationMS is also an exec's, how
+	// long the command ran (#141). Omitted on every other entry.
 	Principal  string `json:"principal,omitempty"`
 	DurationMS int64  `json:"duration_ms,omitempty"`
 	Reason     string `json:"reason,omitempty"`

internal/jails/exec.go

@@ -3,12 +3,14 @@ package jails
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"regexp"
 	"sort"
 	"strings"
 	"time"
 
+	"github.com/ottermq/jaildeck/internal/audit"
 	"github.com/ottermq/jaildeck/internal/common"
 )
 
@@ -118,7 +120,7 @@ func (s *JailService) Exec(ctx context.Context, name JailName, request ExecReque
 	result, err := s.exec.ExecInJail(opCtx, name.String(), argv, env, timeout)
 	result.Jail, result.Argv, result.Timeout = name.String(), request.Argv, timeout.String()
 
-	s.logStep(opCtx, OperationExec, name.String(), execCommandLine(name.String(), argv, env), err)
+	s.logExec(opCtx, name.String(), execCommandLine(name.String(), argv, env), result, err)
 	if err != nil {
 		return result, err
 	}
@@ -203,3 +205,29 @@ func execCommandLine(name string, argv []string, env map[string]string) string {
 	}
 	return strings.Join(append(parts, argv...), " ")
 }
+
+// logExec audits an exec. A command that could not be run is a failed entry,
+// as for any step. One that ran is a successful exec whatever it exited with
+// (JD-016), and its entry carries the command's own exit code, whether it was
+// stopped by the timeout, and how long it took (#141): "what did that token
+// run, and what came of it" is what the entry is for.
+func (s *JailService) logExec(ctx context.Context, target, command string, result ExecResult, err error) {
+	if err != nil {
+		s.logStep(ctx, OperationExec, target, command, err)
+		return
+	}
+	entry := audit.Entry{
+		Timestamp:  time.Now(),
+		Operation:  OperationExec,
+		Target:     target,
+		Command:    command,
+		Success:    true,
+		ExitCode:   result.ExitCode,
+		TimedOut:   result.TimedOut,
+		DurationMS: result.DurationMS,
+	}
+	if logErr := s.operationLogger.Log(ctx, entry); logErr != nil {
+		common.Logger(ctx, "jail").Error("failed to write operation log",
+			slog.String("operation", OperationExec), slog.String("target", target), slog.Any("err", logErr))
+	}
+}

internal/jails/exec_test.go

@@ -317,3 +317,35 @@ func TestExecAuditsACommandThatCouldNotRun(t *testing.T) {
 		t.Errorf("entries = %+v, want one failed entry", logger.entries)
 	}
 }
+
+// A command that ran is a successful exec whatever it exited with (JD-016),
+// and its entry says what it exited with: an entry claiming exit 0 for a
+// command that failed, as it used to, answers the one question the entry is
+// for wrongly (#141).
+func TestExecAuditsWhatTheCommandDid(t *testing.T) {
+	for _, tc := range []struct {
+		name   string
+		result ExecResult
+	}{
+		{"exited non-zero", ExecResult{ExitCode: 3, DurationMS: 12}},
+		{"timed out", ExecResult{ExitCode: -1, TimedOut: true, DurationMS: 5000}},
+		{"exited 0", ExecResult{ExitCode: 0, DurationMS: 7}},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			logger := &fakeLogger{}
+			service := execService(aRunningJail(), &stubExecutor{result: tc.result}, logger)
+			if _, err := service.Exec(context.Background(), "db1", anExec()); err != nil {
+				t.Fatalf("Exec: %v", err)
+			}
+			if len(logger.entries) != 1 {
+				t.Fatalf("wrote %d entries", len(logger.entries))
+			}
+			e := logger.entries[0]
+			if !e.Success || e.ExitCode != tc.result.ExitCode || e.TimedOut != tc.result.TimedOut ||
+				e.DurationMS != tc.result.DurationMS || e.Error != "" {
+				t.Errorf("entry = %+v, want success with exit %d, timed_out %v, %d ms",
+					e, tc.result.ExitCode, tc.result.TimedOut, tc.result.DurationMS)
+			}
+		})
+	}
+}

internal/jails/handler.go

@@ -1123,7 +1123,9 @@ func (h *JailHandler) Ensure(w http.ResponseWriter, r *http.Request) {
 // @Description
 // @Description  Every call is audited with the command line it became, which includes any
 // @Description  environment values: a secret passed this way is written to the audit log,
-// @Description  which is `0700` and root-owned for that kind of reason.
+// @Description  which is `0700` and root-owned for that kind of reason. A command that ran is
+// @Description  a successful entry whatever it exited with, and the entry carries what came of
+// @Description  it: its `exit_code`, `timed_out`, and `duration_ms`.
 // @Tags         jails
 // @Accept       json
 // @Produce      json