diff --git a/DESIGN.md b/DESIGN.md index 270351e..27abacb 100644 --- a/DESIGN.md +++ b/DESIGN.md @@ -1880,14 +1880,20 @@ and the alarm comes. Run the job as its own system user (see at once, before any message (503), and sends one alert message. The file may now end in a torn line, and the broker records it at the next start (below). -- After an entry is on disk, the broker writes `audit anchor SEQ:HASH` to - stderr: the entry's number and the hash of its line. It never writes the - content of an entry there. If this write fails, it counts as a failed - write too. +- After an entry is on disk, the broker writes `audit anchor SEQ:HASH LOGID` + to stderr: the entry's number, the hash of its line, and the log ID. + The log ID is the SHA-256 of line 1 of the log, as 64 hex digits. It + names the log, so anchors of two logs can be told apart. It never writes + the content of an entry there. If this write fails, it counts as a + failed write too. +- When the broker opens the log, it writes `audit open SEQ:HASH LOGID`: the + number and hash of the last entry it found, and the log ID. A log with + no line 1 yet has the head `0:` and 64 zeros, and the log ID is 64 + zeros. This is a new log. - `nodkey audit verify FILE` checks every line and prints the first problem. With anchors (`--anchor SEQ:HASH`, or `--anchors FILE` for a copy of the journal), it also checks that each entry `SEQ` has that - hash. The rules are below. The output and the exit codes are in section + hash, and that each open line matches the log (below). The rules are below. The output and the exit codes are in section 15. The fields of each event, after `seq`, `time`, `event` and `prev`: @@ -2024,12 +2030,38 @@ shows as an anchor whose entry is not there, or, if the broker wrote more entries after the cut, as two anchors for one entry that differ. Entries after the newest anchor are not proven. +**The open line.** The last anchor before a stop is the head of the log at +the stop. At the next start, the open line is the head that the broker +finds. So `audit verify` checks each open line of this log against the +last anchor of this log before it. If someone added, removed or changed +an entry while the broker was stopped, the two differ, and the check +fails. Only anchors and open lines with the log ID of the checked log are +used. Anchor lines from earlier versions have no log ID; they count as +anchors of the checked log. An open line of a new log (zero log ID) is +not checked, and is counted as a "new log start". + +**Other logs.** The journal can hold lines of other logs, such as after a +person moved the log away and the broker started a new one. `audit verify` +does not check them. It prints each one: `other log in the journal: ID …, +up to entry N; if no person moved it away, it was deleted or replaced`. +A deleted log and a log moved away on purpose look the same in the +journal, so the person decides. They can check the old log with the same +journal. + What the anchors do not find: - An entry that someone appends while the broker is stopped, with the right `seq` and `prev`. At the next start, the broker takes it as the - last entry, and every later anchor covers it. Only the missing - `audit anchor` line for that entry shows it. + last entry, and every later anchor covers it. The open line shows it: + its head is not the last anchor. Without the open lines (a journal + from an earlier version), only the missing `audit anchor` line for + that entry shows it. +- A crash after the entry is synced but before its anchor reaches the + journal (journald can lose its last lines in a power cut). The next + open line then does not match the last anchor. `audit verify` fails. + This fails closed: the person checks the log and the time of the + crash, and then knows it was not an attack. It cannot tell the two + apart by itself. - On Linux, `chattr +a` on the file stops anyone except root from changing old lines. It does not stop the broker user from appending. For example, it can append a `log_recovered` entry that names the last real entry as @@ -2039,8 +2071,10 @@ What the anchors do not find: nothing alerts at the start. The anchor of that last real entry then does not match, so check with every anchor. - If a person moves the log away, the broker starts a new log at entry 1. - The journal then has anchors of both logs, and they differ. Use only the - anchors since the new log began, and keep the old file. + The journal then has lines of both logs. They have different log IDs, so + `audit verify` checks the new log and shows the old one as "other log + in the journal", not as a failure. But a deleted log looks the same, + so the person must know whether they moved it. Keep the old file. THREAT-MODEL.md T17 lists the risk that remains. @@ -2066,8 +2100,11 @@ is not a valid entry or is longer than 64 KiB. Something other than a power cut changed the file then. A second power cut during the recovery write itself can also leave the file like this. Then run `nodkey audit verify` to see where. Keep the file, move it away, and let -the broker start a new log. Check the new log only with the anchors since -it began. +the broker start a new log. `audit verify` checks the new log with the +whole journal; the old log shows as another log (above). This needs a +journal with log IDs: if the journal still has anchor lines without a +log ID (from an earlier version), check the new log only with the lines +since it began, such as `journalctl -u nodkey -o cat --since TIME`. **What `nodkey audit verify` checks.** It reads the file line by line, so the file can be large. @@ -2412,7 +2449,7 @@ a field of its certificate, or a line break: broker never logs claimed text, except the version that a client claims when it is a release version, which is only digits and dots (see "Versions" above), and cuts each value to 1 KiB. So no line - can start with `audit anchor ` (section 9), and none comes near the + can start with `audit anchor ` or `audit open ` (section 9), and none comes near the 48 KiB at which journald splits a line. It logs at most 20 requests in a minute that a check refused, SSH logins (section 6) and variables on the deny list (section 5), and counts the others. @@ -3550,8 +3587,13 @@ takes `FILE` before or after the options. - `--anchor SEQ:HASH` may repeat. - `--anchors FILE` reads anchors from a file, or from stdin for `-`. It - uses every line that is exactly `audit anchor SEQ:HASH`, and skips the - other lines, so it takes the output of `journalctl -u nodkey -o cat`. + uses every line that is exactly `audit anchor SEQ:HASH LOGID` or + `audit open SEQ:HASH LOGID`, and skips the other lines, so it takes the + output of `journalctl -u nodkey -o cat`. A line `audit anchor SEQ:HASH` + without a log ID (from an earlier version) counts as an anchor of the + checked log. Lines with another log ID are not checked, and are shown. + Each open line of the checked log must equal the last anchor of that log + before it. If no line is an anchor, that is wrong usage (64, with the one line of a usage error): a check with no anchor must not pass by mistake. - Two anchors for one entry must not differ. @@ -3562,10 +3604,16 @@ passes, it prints to stdout: ``` ok: 1234 entries (torn lines: 0) anchors: 1234 checked, all match; the newest is entry 1234 +log ID: 5c2e0b8f4a1d7e3396b0c1f2a8d4e5f60718293a4b5c6d7e8f90a1b2c3d4e5f6 +open lines: 12 checked, all match the anchor before them; new log starts: 1 +other log in the journal: ID 0f1e2d3c4b5a69788796a5b4c3d2e1f00112233445566778899aabbccddeeff0, up to entry 57; if no person moved it away, it was deleted or replaced last entry: 1234:9f86d081884c7d659a2feaa0c55ad015a3bf4f1b2b0b822cd15d6c15b0f00a08 ``` -Without anchors, the middle line is `anchors: none checked`. Entries after +The `log ID`, `open lines` and `other log` lines appear only with +`--anchors`. There is one `other log` line for each other log ID in the +journal, and none if there is no other log. Without anchors, the +`anchors` line is `anchors: none checked`. Entries after the newest anchor are not proven. When the log fails, it prints the first problem to stderr, with the line number, for example `nodkey: audit log FILE: line 57: has seq 58, want 57`. It never prints the @@ -3576,7 +3624,7 @@ text of a line. It exits with: | 0 | the log passed | | 1 | the result cannot be printed | | 64 | wrong usage, such as an anchor that is not `SEQ:HASH`, or an anchors file without an anchor | -| 65 | the log failed: a broken link, a line that is not a valid entry, a torn line without its `log_recovered` entry, an anchor that does not match or whose entry is not in the log, or two anchors for one entry that differ | +| 65 | the log failed: a broken link, a line that is not a valid entry, a torn line without its `log_recovered` entry, an anchor that does not match or whose entry is not in the log, two anchors for one entry that differ, or an open line that does not match the last anchor before it | | 66 | the log or the anchors file cannot be opened or read | `nodkey update [--version X.Y.Z] [--gh PATH] [--reinstall | --notes]` installs a diff --git a/THREAT-MODEL.md b/THREAT-MODEL.md index 78a05c3..16dceed 100644 --- a/THREAT-MODEL.md +++ b/THREAT-MODEL.md @@ -456,7 +456,9 @@ Each entry holds the hash of the one before. That finds accidental damage and simple edits, but not a careful attacker: with write access they can change a line and compute every later hash again, or remove entries from the end. So the broker also writes each entry's number and hash to the -systemd journal (`audit anchor SEQ:HASH`), after the entry is on disk. The +systemd journal (`audit anchor SEQ:HASH LOGID`, where LOGID is the SHA-256 +of line 1 of the log), after the entry is on disk. When it opens the log, +it also writes `audit open SEQ:HASH LOGID` with the head it found. The broker's own user cannot change the journal, so a break-in as that user cannot hide its tracks there, if the journal is kept on disk long enough. Forward the journal to another machine, and not even root on the broker @@ -465,7 +467,10 @@ host can change the copies. Check the log with every anchor since it began restart, the broker builds on the log as it finds it, so its new anchors also cover a change made while it was stopped. With every anchor, a changed entry and a cut log are found, also when the broker wrote more entries -after the cut. A torn line from a power cut is not part of the chain, but +after the cut. The open line closes the gap of a stop: `audit verify` +checks that each open line equals the last anchor of the same log before +it, so an entry added, removed or changed while the broker was stopped is +found. A torn line from a power cut is not part of the chain, but its `log_recovered` entry holds the torn line's length and hash, so a change to it or its removal is found too. The broker locks the log, so a second broker cannot write to it. `nodkey audit verify` never prints the @@ -473,7 +478,8 @@ text of a line, only line numbers, because a line can hold a secret that the masking missed (T15). On Linux, `chattr +a` makes the file append-only for everyone except root. The anchor lines are trusted only because no other broker output can -print a line that is exactly `audit anchor SEQ:HASH`: not a log line, a +print a line that is exactly `audit anchor SEQ:HASH LOGID` or +`audit open SEQ:HASH LOGID`: not a log line, a panic, a server error or a child program's error output. A false anchor line could make a good log fail, or make entries after the newest real anchor look checked. So the broker logs with slog's text handler, whose @@ -493,22 +499,36 @@ Risk that remains: - Entries after the newest copied anchor can be removed unseen. - When a write to stderr fails, the entry is on disk but its anchor is not in the journal. The broker denies the request, stops and exits with - 1 (DESIGN.md section 15). That entry is then like an entry after the - newest anchor. A broken stderr does not kill the broker by SIGPIPE in - the middle of its stop. + 1 (DESIGN.md section 15). At the next start, the open line names that + entry, and `audit verify --anchors` reports a gap. A failed sync or a + power cut that loses journal lines does the same. This fails closed, + but a person must then check the log by hand and check the rest of the + journal with `--since` after that start. A broken stderr does not kill + the broker by SIGPIPE in the middle of its stop. - `chattr +a` does not stop the broker user from appending entries that look right. An entry appended while the broker is stopped, with the right `seq` and `prev`, becomes the last entry at the next start, and - the later anchors cover it. The anchors do not find it; only the missing - `audit anchor` line for that entry shows it. An appended + the later anchors cover it. The anchors alone do not find it, but the + open line does: its head is not the last anchor, so `audit verify` + fails. (Only a journal from before the open line was added has just the + missing `audit anchor` line to show it.) An appended `log_recovered` entry can also make the last real entry look like a torn line. The anchor of that entry finds this. When the forged entry is the last entry, the next start also sends one alert about a torn line; when more entries were appended after it, nothing alerts at the start. -- A log that was removed or moved away looks like a new log. Its anchors - and those of the old log differ, so check with the anchors since the - current log began, and keep the old file. +- A crash after the entry is synced but before its anchor reaches the + journal (journald can lose its last lines in a power cut) makes the next + open line differ from the last anchor. `audit verify` fails. This fails + closed, but it looks like an attack. The person checks the log and the + time of the crash. +- A log that was removed or moved away looks like a new log. Its lines in + the journal have another log ID. `audit verify` shows the old log as + "other log in the journal" and does not fail, because a log that a + person moved on purpose looks the same as a deleted one. A restart at + entry 1 after a deletion is shown this way, but only the person can + tell if the move was on purpose. A moved log is not a cut. Keep the old + file. **T18. The store programs leak a token.** (The `infisical` store is like the `1password` store: no program, no diff --git a/cmd/nodkey/audit.go b/cmd/nodkey/audit.go index 3c50195..df1d7d9 100644 --- a/cmd/nodkey/audit.go +++ b/cmd/nodkey/audit.go @@ -1,14 +1,12 @@ package main import ( - "cmp" "errors" "flag" "fmt" "io" "io/fs" "os" - "slices" "github.com/code6x/nodkey/internal/audit" ) @@ -23,16 +21,21 @@ const ( const auditUsageText = `Usage: nodkey audit verify FILE [--anchor SEQ:HASH]... [--anchors FILE|-] Check the hash chain of an audit log, and that each anchor matches its -entry. The broker writes "audit anchor SEQ:HASH" to the journal for each -entry. Check with every anchor since the log began, not only the newest: +entry. The broker writes "audit anchor SEQ:HASH LOGID" to the journal for +each entry, and "audit open SEQ:HASH LOGID" each time it opens the log. +LOGID is the SHA-256 of line 1 of the log. Check with every anchor since the log began, not only the newest: the newest anchor proves only the entries up to it, and only since it was written. For example: journalctl -u nodkey -o cat | nodkey audit verify FILE --anchors - --anchor SEQ:HASH check that entry SEQ has the hash HASH; may repeat - --anchors FILE read the anchors from FILE, or from stdin for "-": - every line that is exactly "audit anchor SEQ:HASH" + --anchors FILE read the journal lines from FILE, or from stdin for + "-": every line that is exactly "audit anchor + SEQ:HASH LOGID" or "audit open SEQ:HASH LOGID". Each + open line must match the last anchor of its log + before it. Lines of other logs (another LOGID) are + shown, not checked. Exit codes: 0 the log passed, 64 wrong usage, 65 the log failed the check, 66 a file cannot be opened or read, 1 the result cannot be @@ -86,12 +89,13 @@ func runAuditVerify(args []string, stdin io.Reader, stdout, stderr io.Writer) in if fs.NArg() > 0 { return usageFail(stderr, "audit verify", "give one FILE only") } + var journal []audit.JournalLine if anchorsFile.set { - read, code := readAnchorsFile(anchorsFile.value, stdin, stderr) + read, code := readJournalFile(anchorsFile.value, stdin, stderr) if code != exitOK { return code } - anchors = append(anchors, read...) + journal = read } f, err := os.Open(path) //nolint:gosec // G304: the person names the log to check; nodkey only reads it. @@ -102,7 +106,12 @@ func runAuditVerify(args []string, stdin io.Reader, stdout, stderr io.Writer) in _, _ = fmt.Fprintf(stderr, "nodkey: audit log %q: %v\n", path, err) return exitNoInput } - res, err := audit.Verify(f, anchors...) + var res audit.Result + if anchorsFile.set { + res, err = audit.VerifyJournal(f, journal, anchors...) + } else { + res, err = audit.Verify(f, anchors...) + } _ = f.Close() // read only; a close error changes nothing if ve := (*audit.VerifyError)(nil); errors.As(err, &ve) { _, _ = fmt.Fprintf(stderr, "nodkey: audit log %q: %v\n", path, ve) @@ -117,8 +126,17 @@ func runAuditVerify(args []string, stdin io.Reader, stdout, stderr io.Writer) in if res.Anchors == 0 { out += "anchors: none checked\n" } else { - newest := slices.MaxFunc(anchors, func(a, b audit.Anchor) int { return cmp.Compare(a.Seq, b.Seq) }) - out += fmt.Sprintf("anchors: %d checked, all match; the newest is entry %d\n", res.Anchors, newest.Seq) + out += fmt.Sprintf("anchors: %d checked, all match; the newest is entry %d\n", res.Anchors, + newestAnchor(res.LogID, anchors, journal)) + } + if anchorsFile.set { + out += fmt.Sprintf("log ID: %s\n", res.LogID) + out += fmt.Sprintf("open lines: %d checked, all match the anchor before them; new log starts: %d\n", + res.Opens, res.NewStarts) + for _, o := range res.OtherLogs { + out += fmt.Sprintf("other log in the journal: ID %s, up to entry %d; "+ + "if no person moved it away, it was deleted or replaced\n", o.LogID, o.Newest) + } } // The last line is the last entry. Entries after the newest anchor are // not proven. @@ -129,10 +147,27 @@ func runAuditVerify(args []string, stdin io.Reader, stdout, stderr io.Writer) in return exitOK } -// readAnchorsFile reads the anchors of --anchors: from stdin for "-", -// else from the file at path. A file with no anchor is wrong usage: the -// person meant to check anchors, and none would be checked. -func readAnchorsFile(path string, stdin io.Reader, stderr io.Writer) ([]audit.Anchor, int) { +// newestAnchor returns the highest seq of the anchors that were checked +// against the log with the ID id: the --anchor flags, the journal anchors +// of that log, and the journal anchors without a log ID. +func newestAnchor(id audit.LogID, flags []audit.Anchor, journal []audit.JournalLine) uint64 { + var newest uint64 + for _, a := range flags { + newest = max(newest, a.Seq) + } + for _, j := range journal { + if j.Kind == audit.JournalOldAnchor || (j.Kind == audit.JournalAnchor && j.LogID == id) { + newest = max(newest, j.Anchor.Seq) + } + } + return newest +} + +// readJournalFile reads the journal lines of --anchors: from stdin for +// "-", else from the file at path. A file with no anchor or open line is +// wrong usage: the person meant to check anchors, and none would be +// checked. +func readJournalFile(path string, stdin io.Reader, stderr io.Writer) ([]audit.JournalLine, int) { r := stdin if path != "-" { f, err := os.Open(path) //nolint:gosec // G304: the person names the file with the anchors; nodkey only reads it. @@ -147,16 +182,16 @@ func readAnchorsFile(path string, stdin io.Reader, stderr io.Writer) ([]audit.An defer func() { _ = f.Close() }() // read only; a close error changes nothing r = f } - anchors, err := audit.ReadAnchors(r) + lines, err := audit.ReadJournal(r) if err != nil { _, _ = fmt.Fprintf(stderr, "nodkey: audit verify: --anchors %.64q: %v\n", path, err) return nil, exitNoInput } - if len(anchors) == 0 { - return nil, usageFail(stderr, "audit verify", fmt.Sprintf("--anchors %.64q: no line is exactly %q and an anchor; "+ - "use journalctl -o cat", path, audit.JournalPrefix)) + if len(lines) == 0 { + return nil, usageFail(stderr, "audit verify", fmt.Sprintf("--anchors %.64q: no line is exactly %q or %q "+ + "and an anchor; use journalctl -o cat", path, audit.JournalPrefix, audit.JournalOpenPrefix)) } - return anchors, exitOK + return lines, exitOK } // anchorList is the --anchor flag. It may repeat. diff --git a/cmd/nodkey/audit_test.go b/cmd/nodkey/audit_test.go index 68c4754..63333df 100644 --- a/cmd/nodkey/audit_test.go +++ b/cmd/nodkey/audit_test.go @@ -92,6 +92,27 @@ func TestAuditVerify(t *testing.T) { } ok := "ok: 3 entries (torn lines: 0)\n" + id := hashes[0] // the log ID: the hash of line 1 + idLines := func(opens, starts int) string { + return "log ID: " + id + "\n" + fmt.Sprintf("open lines: %d checked, all match the anchor before them; "+ + "new log starts: %d\n", opens, starts) + } + // The journal of the log with log IDs: the broker opened a new log, + // wrote entries 1 and 2, stopped, opened the log again, and wrote 3. + withIDs := "audit open 0:" + zeros + " " + zeros + "\n" + + "audit anchor 1:" + hashes[0] + " " + id + "\naudit anchor 2:" + hashes[1] + " " + id + "\n" + + "audit open 2:" + hashes[1] + " " + id + "\naudit anchor 3:" + hashes[2] + " " + id + "\n" + // Someone added entry 3 while the broker was stopped. At the next + // start, the broker opened the log at entry 3. + addedWhileStopped := "audit anchor 1:" + hashes[0] + " " + id + "\naudit anchor 2:" + hashes[1] + " " + id + "\n" + + "audit open 3:" + hashes[2] + " " + id + "\n" + // An earlier log (run1) was deleted, or moved away, and the broker + // started the log of path at entry 1. + otherID := h1[0] + afterOther := "audit open 0:" + zeros + " " + zeros + "\n" + + "audit anchor 1:" + h1[0] + " " + otherID + "\naudit anchor 2:" + h1[1] + " " + otherID + "\n" + + "audit open 0:" + zeros + " " + zeros + "\n" + + "audit anchor 1:" + hashes[0] + " " + id + "\naudit anchor 2:" + hashes[1] + " " + id + "\n" last := "last entry: 3:" + hashes[2] + "\n" tests := []struct { name string @@ -112,12 +133,22 @@ func TestAuditVerify(t *testing.T) { {name: "one anchor twice", args: []string{"audit", "verify", path, "--anchor", "2:" + hashes[1], "--anchor", "2:" + hashes[1]}, wantCode: exitOK, wantStdout: ok + "anchors: 1 checked, all match; the newest is entry 2\n" + last}, {name: "anchors from a file", args: []string{"audit", "verify", path, "--anchors", anchorsFile}, wantCode: exitOK, - wantStdout: ok + "anchors: 3 checked, all match; the newest is entry 3\n" + last}, + wantStdout: ok + "anchors: 3 checked, all match; the newest is entry 3\n" + idLines(0, 0) + last}, {name: "anchors from stdin", args: []string{"audit", "verify", "--anchors", "-", path}, stdin: journalText, wantCode: exitOK, - wantStdout: ok + "anchors: 3 checked, all match; the newest is entry 3\n" + last}, + wantStdout: ok + "anchors: 3 checked, all match; the newest is entry 3\n" + idLines(0, 0) + last}, {name: "anchors from stdin and an anchor", stdin: journal(1, hashes[0]), wantCode: exitOK, args: []string{"audit", "verify", path, "--anchors=-", "--anchor", "3:" + hashes[2]}, - wantStdout: ok + "anchors: 2 checked, all match; the newest is entry 3\n" + last}, + wantStdout: ok + "anchors: 2 checked, all match; the newest is entry 3\n" + idLines(0, 0) + last}, + {name: "journal with log IDs", args: []string{"audit", "verify", path, "--anchors", "-"}, stdin: withIDs, + wantCode: exitOK, wantStdout: ok + "anchors: 3 checked, all match; the newest is entry 3\n" + idLines(1, 1) + last}, + {name: "entry added while the broker was stopped", args: []string{"audit", "verify", path, "--anchors", "-"}, + stdin: addedWhileStopped, wantCode: exitDataErr, + wantStderr: "journal line 3: the broker opened the log at entry 3, but the last anchor of this log before it is " + + "entry 2: entries were added or removed while the broker was stopped"}, + {name: "a deleted or moved log is shown, not a cut", args: []string{"audit", "verify", path, "--anchors", "-"}, + stdin: afterOther, wantCode: exitOK, wantStdout: ok + "anchors: 2 checked, all match; the newest is entry 2\n" + + idLines(0, 2) + "other log in the journal: ID " + otherID + ", up to entry 2; " + + "if no person moved it away, it was deleted or replaced\n" + last}, {name: "wrong anchor", args: []string{"audit", "verify", path, "--anchor", "2:" + hashes[2]}, wantCode: exitDataErr, wantStderr: "nodkey: audit log " + strconv.Quote(path) + ": line 2: is entry 2, and its hash is not the hash in the anchor\n"}, {name: "two anchors for one entry", args: []string{"audit", "verify", path, "--anchor", "2:" + hashes[1], "--anchor", "2:" + hashes[2]}, @@ -140,7 +171,7 @@ func TestAuditVerify(t *testing.T) { {name: "missing anchors file", args: []string{"audit", "verify", path, "--anchors", anchorsFile + ".missing"}, wantCode: exitNoInput, wantStderr: "nodkey: audit verify: --anchors \""}, {name: "anchors file without an anchor line", args: []string{"audit", "verify", path, "--anchors", noAnchors}, - wantCode: exitUsage, wantStderr: `no line is exactly "audit anchor " and an anchor; use journalctl -o cat`}, + wantCode: exitUsage, wantStderr: `no line is exactly "audit anchor " or "audit open " and an anchor; use journalctl -o cat`}, {name: "empty stdin for anchors", args: []string{"audit", "verify", path, "--anchors", "-"}, wantCode: exitUsage, wantStderr: `--anchors "-": no line is exactly`}, {name: "anchors twice", args: []string{"audit", "verify", path, "--anchors", anchorsFile, "--anchors", "-"}, diff --git a/cmd/nodkey/broker_test.go b/cmd/nodkey/broker_test.go index 6cc0232..f04e0b7 100644 --- a/cmd/nodkey/broker_test.go +++ b/cmd/nodkey/broker_test.go @@ -22,24 +22,32 @@ import ( "golang.org/x/crypto/ssh" + "github.com/code6x/nodkey/internal/audit" "github.com/code6x/nodkey/internal/broker" "github.com/code6x/nodkey/internal/config" "github.com/code6x/nodkey/internal/sshauth" "github.com/code6x/nodkey/internal/telegram" ) -// fakeAnchor is a line that looks like an audit anchor (DESIGN.md section -// 9). No line of the broker may start with "audit anchor ". -var fakeAnchor = "audit anchor 1:" + strings.Repeat("ab", 32) +// fakeAnchor is text with an audit anchor line and an audit open line +// (DESIGN.md section 9), each with a log ID, on lines of their own. No +// line of the broker may start with "audit anchor " or "audit open ". +var fakeAnchor = "audit anchor 1:" + strings.Repeat("ab", 32) + " " + strings.Repeat("ab", 32) + + "\naudit open 1:" + strings.Repeat("ab", 32) + " " + strings.Repeat("ab", 32) + "\n" -// noAnchorLine fails if a line of out starts like an audit anchor. +// noAnchorLine fails if a line of out starts like an audit anchor or an +// audit open line, or if audit.ReadJournal finds such a line in out. func noAnchorLine(t *testing.T, out string) { t.Helper() for line := range strings.SplitSeq(out, "\n") { - if strings.HasPrefix(line, "audit anchor ") { + if strings.HasPrefix(line, audit.JournalPrefix) || strings.HasPrefix(line, audit.JournalOpenPrefix) { t.Errorf("a line looks like an audit anchor: %q", line) } } + lines, err := audit.ReadJournal(strings.NewReader(out)) + if err != nil || len(lines) != 0 { + t.Errorf("audit.ReadJournal found %d journal lines in the broker's output (error %v)", len(lines), err) + } } func TestBrokerUsage(t *testing.T) { diff --git a/docs/setup.md b/docs/setup.md index da32bc5..aedabc2 100644 --- a/docs/setup.md +++ b/docs/setup.md @@ -1508,9 +1508,16 @@ keeps them. Without a working log, the broker stops. When a write to stderr fails, for example because the program that reads it ended, the broker stops in its normal order and exits with code 1. The example unit then starts it -again after 5 seconds. The audit log stays whole: an entry whose anchor -did not reach the journal is still checked by `nodkey audit verify`, -like any entry after the newest anchor. +again after 5 seconds. The entry whose anchor did not reach the journal +is on disk. At the next start, the broker writes an `audit open` line at +that entry, and `nodkey audit verify --anchors` then reports that +entries were added while the broker was stopped. A failed sync and a +power cut can do the same: journald may lose its last minutes of lines. +Then look at the log near that entry and at the time of the stop. If you +are sure the gap has a cause like this, check the log with only the +journal lines after that start: `journalctl -u nodkey -o cat --since +TIME`, where TIME is a moment after that start. This works once the +broker has written at least one entry after that start. ## 10. Start the broker @@ -1534,15 +1541,19 @@ level=INFO msg="nodkey broker: core dumps are off: the soft and the hard limit o level=INFO msg="nodkey broker: the TLS key is loaded" pin=sha256:Q2b9... level=INFO msg="nodkey broker: an SSH key is loaded and can sign" key=deploy fingerprint=SHA256:3SMw... level=INFO msg="nodkey broker: the audit log is open" path=/var/lib/nodkey/audit.jsonl +audit open 0:0000000000000000000000000000000000000000000000000000000000000000 0000000000000000000000000000000000000000000000000000000000000000 level=INFO msg="nodkey broker: a store started" store=main level=INFO msg="nodkey broker: the listen address is open; nothing reads from it yet" address=192.0.2.10:7743 -audit anchor 1:8318bd865cb1923faea0c3a1837f636ad1f8781898606701949120d612c85da0 +audit anchor 1:8318bd865cb1923faea0c3a1837f636ad1f8781898606701949120d612c85da0 8318bd865cb1923faea0c3a1837f636ad1f8781898606701949120d612c85da0 level=INFO msg="nodkey broker: the approver runs: it polls Telegram for the answers" level=INFO msg="nodkey broker: listening; the broker is ready" address=192.0.2.10:7743 ``` -The lines `audit anchor SEQ:HASH` are the anchors of the audit log -([section 12](#12-check-the-audit-log)). When something is wrong, the +The lines `audit anchor SEQ:HASH LOGID` and `audit open SEQ:HASH LOGID` +are the anchors of the audit log +([section 12](#12-check-the-audit-log)). LOGID names the log. On a new +log, the open line has a zero head and a zero LOGID, and comes before the +first anchor. When something is wrong, the broker logs why ([section 14](#14-when-something-does-not-work)). A restart of the broker ends all grants, and denies the requests that @@ -1935,7 +1946,9 @@ Things to know: The broker writes each request and each decision to the audit log, `/var/lib/nodkey/audit.jsonl`. Each entry holds the hash of the entry before it, and the broker writes the hash of each entry to the journal: -`audit anchor SEQ:HASH` +`audit anchor SEQ:HASH LOGID`. When it opens the log, it writes +`audit open SEQ:HASH LOGID`, the last entry that it found. LOGID is the +SHA-256 of line 1 of the log ([DESIGN.md section 9](../DESIGN.md#9-audit-log)). Check the log with every anchor since the log began, as root: @@ -1948,19 +1961,37 @@ A good log gives: ```text ok: 1234 entries (torn lines: 0) anchors: 1234 checked, all match; the newest is entry 1234 +log ID: 5c2e0b8f4a1d7e3396b0c1f2a8d4e5f60718293a4b5c6d7e8f90a1b2c3d4e5f6 +open lines: 12 checked, all match the anchor before them; new log starts: 1 last entry: 1234:9f86d081884c7d659a2feaa0c55ad015a3bf4f1b2b0b822cd15d6c15b0f00a08 ``` It exits with 0 when the log passed, and with 65 when it found a problem. Then it prints the line number, never the text of the line. A changed entry shows as an anchor that does not match. A log that someone -cut shows as an anchor whose entry is missing. +cut shows as an anchor whose entry is missing. An entry that someone +added, removed or changed while the broker was stopped shows as an open +line that does not match the last anchor before it. - Entries after the newest anchor are not proven. -- If you moved the log away, the broker starts a new log at entry 1. - Check the new log only with the anchors since then, such as - `journalctl -u nodkey -o cat --since "2026-10-20 10:00"`, and keep - the old file. +- An open line that does not match can also come from a crash: the + entry was on disk, but the power went before its anchor reached the + journal. `nodkey audit verify` cannot tell. Look at the log around that + entry and at the time of the crash. +- If journald removed its oldest lines (`SystemMaxUse=` or its age + limits), the first line of the log in the journal can be an `audit + open` line with no anchor before it, and the check fails. Keep the + journal for as long as the log, or copy it to another machine. +- Anchor lines without a log ID come from an earlier version. They count + as anchors of the log you check. If the journal has such lines of more + than one log, check each log with only the lines since it began, with + `--since`. +- If the journal holds lines of another log, `nodkey audit verify` prints + `other log in the journal: ID …, up to entry N; if no person moved it + away, it was deleted or replaced`. If you moved the log away, this is + expected: the broker started a new log at entry 1. If you did not, + someone deleted or replaced the log. Keep the old file. It does not + fail the check. - `jq` shows the entries in short, for example the last ten: ```sh diff --git a/internal/audit/anchor.go b/internal/audit/anchor.go index 3593ad9..d9c5c3d 100644 --- a/internal/audit/anchor.go +++ b/internal/audit/anchor.go @@ -13,10 +13,18 @@ import ( ) // JournalPrefix starts each line that Append writes to the journal. The -// rest of the line is the entry's anchor, such as -// "audit anchor 12:9f86d081…", ready for nodkey audit verify. +// rest of the line is the entry's anchor and the log ID, such as +// "audit anchor 12:9f86d081… 3a7bd3e2…", ready for nodkey audit verify. +// Earlier versions wrote the anchor only, without the log ID; ReadJournal +// still reads that old form. const JournalPrefix = "audit anchor " +// JournalOpenPrefix starts the line that Open writes to the journal, once, +// such as "audit open 12:9f86d081… 3a7bd3e2…": the last entry that Open +// found in the log, and the log ID. A log with no complete line has the +// head "0:" and 64 zeros, and the log ID 64 zeros. +const JournalOpenPrefix = "audit open " + // Anchor names one entry: its seq and the SHA-256 of its line. Written as // text, it is "SEQ:HASH", such as "12:9f86d081…" with 64 hex digits. // @@ -24,7 +32,10 @@ const JournalPrefix = "audit anchor " // broker wrote it. It does not prove what happened before: after a // restart, the broker builds on the log as it finds it, so its new // anchors cover any change made while it was stopped. So check a log with -// every anchor since the log began, not only the newest one. +// every anchor since the log began, not only the newest one. The "audit +// open" line of each start closes the gap: it holds the last entry that +// Open found, and VerifyJournal checks that it is the last anchor before +// it. So an entry added or changed while the broker was stopped is found. type Anchor struct { Seq uint64 Hash [sha256.Size]byte @@ -56,21 +67,116 @@ func ParseAnchor(s string) (Anchor, error) { return a, nil } +// LogID names one log: the SHA-256 of its first line, the bytes before +// the first newline. It tells the lines of two logs apart in one journal, +// such as of a log that was deleted and of the new log after it. It is +// zero while the log has no newline yet: then it is empty, or one torn +// line. +type LogID [sha256.Size]byte + +// String returns the log ID as 64 lowercase hex digits. +func (id LogID) String() string { return hex.EncodeToString(id[:]) } + +// IsZero reports whether id is 64 zeros: the log had no line 1 yet. +func (id LogID) IsZero() bool { return id == LogID{} } + +// JournalKind is the kind of a journal line. +type JournalKind int + +// The kinds of journal lines. +const ( + // JournalAnchor is "audit anchor SEQ:HASH LOGID", from Append. + JournalAnchor JournalKind = iota + 1 + // JournalOldAnchor is "audit anchor SEQ:HASH", from Append of an + // earlier version. It has no log ID; VerifyJournal takes it as an + // anchor of the log that it checks. + JournalOldAnchor + // JournalOpen is "audit open SEQ:HASH LOGID", from Open. + JournalOpen +) + +// JournalLine is one line of the journal that ReadJournal found. +type JournalLine struct { + // Line is the line number in the journal copy, from 1. + Line uint64 + Kind JournalKind + // Anchor is the entry of an anchor line, or for an open line, the + // last entry that Open found. That is seq 0 and a zero hash for a log + // with no complete line. + Anchor Anchor + // LogID is the log ID. It is zero for JournalOldAnchor, and for an + // open line of a log that had no line 1 yet. + LogID LogID +} + +// parseJournalLine reads one line, without its line end. It reports false +// for every line that is not exactly an anchor or an open line. SEQ:HASH +// must be in the form that Anchor.String writes: no leading zero in SEQ, +// and lowercase hex. +func parseJournalLine(line []byte) (JournalLine, bool) { + if rest, ok := bytes.CutPrefix(line, []byte(JournalPrefix)); ok { + anchorText, idText, hasID := bytes.Cut(rest, []byte(" ")) + a, err := ParseAnchor(string(anchorText)) + if err != nil || a.String() != string(anchorText) { + return JournalLine{}, false + } + if !hasID { + return JournalLine{Kind: JournalOldAnchor, Anchor: a}, true + } + var id LogID + // Append writes an anchor only after entry 1, so its log ID is + // never zero. + if !decodeHex64((*[sha256.Size]byte)(&id), string(idText)) || id.IsZero() { + return JournalLine{}, false + } + return JournalLine{Kind: JournalAnchor, Anchor: a, LogID: id}, true + } + if rest, ok := bytes.CutPrefix(line, []byte(JournalOpenPrefix)); ok { + anchorText, idText, hasID := bytes.Cut(rest, []byte(" ")) + if !hasID { + return JournalLine{}, false + } + var id LogID + if !decodeHex64((*[sha256.Size]byte)(&id), string(idText)) { + return JournalLine{}, false + } + var a Anchor + if string(anchorText) != "0:"+zeroHash { + var err error + if a, err = ParseAnchor(string(anchorText)); err != nil || a.String() != string(anchorText) { + return JournalLine{}, false + } + } + // A log with a newline has a complete line, so it has entries. + // A log without one has neither. + if (a.Seq == 0) != id.IsZero() { + return JournalLine{}, false + } + return JournalLine{Kind: JournalOpen, Anchor: a, LogID: id}, true + } + return JournalLine{}, false +} + +// zeroHash is 64 zeros: the hash of the head of an open line for a log +// with no entry. +var zeroHash = strings.Repeat("0", 2*sha256.Size) + // maxAnchorLine is longer than any journal line with an anchor. A longer // line is skipped without being read into memory. const maxAnchorLine = 256 -// ReadAnchors reads the anchors from a copy of the journal, such as the -// output of journalctl -o cat. It uses only the lines that are exactly -// JournalPrefix and an anchor, with a newline or a carriage return and a -// newline at the end. It skips every other line, so the broker's other log -// lines may be there too. It returns the anchors in the order of the -// lines; Verify refuses two anchors for one entry with different hashes. -// An error is only a read error, and it never holds text from r. -func ReadAnchors(r io.Reader) ([]Anchor, error) { +// ReadJournal reads the anchor and open lines from a copy of the journal, +// such as the output of journalctl -o cat. It uses only the lines that are +// exactly one of the forms of JournalKind, with a newline or a carriage +// return and a newline at the end; the last line may have no line end. +// It skips every other line, so the +// broker's other log lines may be there too. It returns the lines in the +// order of the journal: VerifyJournal needs that order. An error is only a +// read error, and it never holds text from r. +func ReadJournal(r io.Reader) ([]JournalLine, error) { br := bufio.NewReaderSize(r, maxAnchorLine) - var anchors []Anchor - for no := 1; ; no++ { + var lines []JournalLine + for no := uint64(1); ; no++ { line, err := br.ReadSlice('\n') long := false for errors.Is(err, bufio.ErrBufferFull) { // skip the rest of a long line @@ -78,18 +184,38 @@ func ReadAnchors(r io.Reader) ([]Anchor, error) { _, err = br.ReadSlice('\n') } if !long { - line = bytes.TrimSuffix(bytes.TrimSuffix(line, []byte("\n")), []byte("\r")) - if rest, ok := bytes.CutPrefix(line, []byte(JournalPrefix)); ok { - if a, perr := ParseAnchor(string(rest)); perr == nil { - anchors = append(anchors, a) - } + if l, ok := bytes.CutSuffix(line, []byte("\n")); ok { + line = bytes.TrimSuffix(l, []byte("\r")) // only a CR before the LF + } + if jl, ok := parseJournalLine(line); ok { + jl.Line = no + lines = append(lines, jl) } } if errors.Is(err, io.EOF) { - return anchors, nil + return lines, nil } if err != nil { - return nil, fmt.Errorf("reading the anchors: line %d: %w", no, err) + return nil, fmt.Errorf("reading the journal: line %d: %w", no, err) + } + } +} + +// ReadAnchors reads the anchors of every "audit anchor" line, in both +// forms, with ReadJournal, and returns them in the order of the lines. It +// does not tell logs apart, and it skips the open lines; VerifyJournal +// does both. An error is only a read error, and it never holds text from +// r. +func ReadAnchors(r io.Reader) ([]Anchor, error) { + lines, err := ReadJournal(r) + if err != nil { + return nil, err + } + var anchors []Anchor + for _, jl := range lines { + if jl.Kind != JournalOpen { + anchors = append(anchors, jl.Anchor) } } + return anchors, nil } diff --git a/internal/audit/anchor_test.go b/internal/audit/anchor_test.go index 210f396..63d9721 100644 --- a/internal/audit/anchor_test.go +++ b/internal/audit/anchor_test.go @@ -61,3 +61,88 @@ func TestReadAnchorsReadError(t *testing.T) { t.Errorf("ReadAnchors = %v; a read error is not a *VerifyError", err) } } + +func TestReadJournal(t *testing.T) { + h1, h2 := sha256.Sum256([]byte("one")), sha256.Sum256([]byte("two")) + a1, a2 := Anchor{Seq: 1, Hash: h1}, Anchor{Seq: 2, Hash: h2} + id := LogID(sha256.Sum256([]byte("line 1"))) + hexID := id.String() + anchor := func(a Anchor) string { return JournalPrefix + a.String() + " " + hexID } + open := func(a Anchor) string { return JournalOpenPrefix + a.String() + " " + hexID } + newOpen := JournalOpenPrefix + "0:" + zeros + " " + zeros + tests := []struct { + name string + text string + want []JournalLine + }{ + {"empty", "", nil}, + {"every kind, in order", "x\n" + open(a1) + "\n" + anchor(a2) + "\n" + JournalPrefix + a1.String() + "\n" + newOpen + "\r\n", + []JournalLine{ + {Line: 2, Kind: JournalOpen, Anchor: a1, LogID: id}, + {Line: 3, Kind: JournalAnchor, Anchor: a2, LogID: id}, + {Line: 4, Kind: JournalOldAnchor, Anchor: a1}, + {Line: 5, Kind: JournalOpen}, + }}, + {"no newline at the end", anchor(a1), []JournalLine{{Line: 1, Kind: JournalAnchor, Anchor: a1, LogID: id}}}, + // Lines that are not exactly one of the forms are skipped. + {"an anchor with a bad hash", JournalPrefix + "1:" + strings.Repeat("g", 64) + " " + hexID + "\n", nil}, + {"an anchor with a short hash", JournalPrefix + "1:abcd " + hexID + "\n", nil}, + {"an anchor with seq 0", JournalPrefix + "0:" + zeros + " " + hexID + "\n", nil}, + {"an anchor with two spaces", JournalPrefix + a1.String() + " " + hexID + "\n", nil}, + {"an anchor with a space at the end", anchor(a1) + " \n", nil}, + {"an anchor with a space at the end, old form", JournalPrefix + a1.String() + " \n", nil}, + {"an anchor with text after", anchor(a1) + " more\n", nil}, + {"an anchor with a short log ID", JournalPrefix + a1.String() + " " + hexID[:62] + "\n", nil}, + {"an anchor with an upper-case log ID", JournalPrefix + a1.String() + " " + strings.ToUpper(hexID) + "\n", nil}, + {"an anchor with a zero log ID", JournalPrefix + a1.String() + " " + zeros + "\n", nil}, + {"an anchor with an upper-case hash", JournalPrefix + "1:" + strings.ToUpper(hex.EncodeToString(h1[:])) + " " + hexID + "\n", nil}, + {"an old-form anchor with an upper-case hash", JournalPrefix + "1:" + strings.ToUpper(hex.EncodeToString(h1[:])) + "\n", nil}, + {"an anchor with a leading zero", JournalPrefix + "0" + a1.String() + " " + hexID + "\n", nil}, + {"an old-form anchor with a leading zero", JournalPrefix + "0" + a1.String() + "\n", nil}, + {"an open with an upper-case hash", JournalOpenPrefix + "1:" + strings.ToUpper(hex.EncodeToString(h1[:])) + " " + hexID + "\n", nil}, + {"an open with a leading zero", JournalOpenPrefix + "0" + a1.String() + " " + hexID + "\n", nil}, + {"an open of entry 00", JournalOpenPrefix + "00:" + zeros + " " + zeros + "\n", nil}, + {"a carriage return at the end without a newline", anchor(a1) + "\r", nil}, + {"a carriage return alone", anchor(a1) + "\r" + anchor(a2) + "\n", nil}, + {"two spaces after the prefix", "audit anchor " + a1.String() + " " + hexID + "\n", nil}, + {"a long line", strings.Repeat("x", 3*maxAnchorLine) + anchor(a1) + "\n" + anchor(a2) + "\n", + []JournalLine{{Line: 2, Kind: JournalAnchor, Anchor: a2, LogID: id}}}, + {"text before", "nodkey[1]: " + anchor(a1) + "\n", nil}, + {"an open without a log ID", JournalOpenPrefix + a1.String() + "\n", nil}, + {"an open with a bad log ID", JournalOpenPrefix + a1.String() + " " + strings.Repeat("x", 64) + "\n", nil}, + {"an open with a space at the end", open(a1) + " \n", nil}, + {"an open with text after", open(a1) + " more\n", nil}, + {"an open with two spaces", JournalOpenPrefix + a1.String() + " " + hexID + "\n", nil}, + {"an open with a bad head", JournalOpenPrefix + "1:xyz " + hexID + "\n", nil}, + {"an open of entry 0 with a hash", JournalOpenPrefix + "0:" + hex.EncodeToString(h1[:]) + " " + zeros + "\n", nil}, + {"an open of entry 0 with a log ID", JournalOpenPrefix + "0:" + zeros + " " + hexID + "\n", nil}, + {"an open of entry 1 with a zero log ID", JournalOpenPrefix + a1.String() + " " + zeros + "\n", nil}, + {"an open too long", open(a1) + strings.Repeat("0", maxAnchorLine) + "\n", nil}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, err := ReadJournal(strings.NewReader(tt.text)) + if err != nil { + t.Fatalf("ReadJournal: %v", err) + } + if len(got) != len(tt.want) { + t.Fatalf("ReadJournal = %+v, want %+v", got, tt.want) + } + for i := range got { + if got[i] != tt.want[i] { + t.Errorf("line %d = %+v, want %+v", i, got[i], tt.want[i]) + } + } + }) + } +} + +func TestLogID(t *testing.T) { + if !(LogID{}).IsZero() || (LogID{}).String() != zeros { + t.Errorf("zero LogID: %q, %v", LogID{}.String(), LogID{}.IsZero()) + } + id := LogID(sha256.Sum256([]byte("x"))) + if id.IsZero() || id.String() != hex.EncodeToString(id[:]) { + t.Errorf("LogID = %q", id.String()) + } +} diff --git a/internal/audit/audit.go b/internal/audit/audit.go index a1081a3..d000d8a 100644 --- a/internal/audit/audit.go +++ b/internal/audit/audit.go @@ -12,7 +12,13 @@ // disk. Append returns an error if that fails, and then every later Append // fails too, so the broker denies every request until it starts again. // The number and hash of each entry also go to a journal writer (stderr in -// the broker), as an anchor that Verify can check later. +// the broker), as an anchor that Verify can check later, with the log ID: +// the SHA-256 of line 1, which tells two logs apart. At each start, Open +// writes one more journal line: the last entry that it found, and the log +// ID. VerifyJournal checks that this entry is the last anchor of the log +// before it, so an entry that was added or changed while the broker was +// stopped is found. A log that starts again at entry 1, such as after a +// delete, has a new log ID, and VerifyJournal names the old one. package audit import ( @@ -67,9 +73,11 @@ type Recovery struct { // Options are what Open needs from the broker. Both fields are required. type Options struct { - // Journal gets one line for each entry: JournalPrefix and the entry's - // anchor. It never gets the content of an entry. In the broker it is - // stderr, which systemd keeps in the journal. + // Journal gets one line from Open: JournalOpenPrefix, the last entry + // that Open found, and the log ID. Then it gets one line for each + // entry: JournalPrefix, the entry's anchor, and the log ID. It never + // gets the content of an entry. In the broker it is stderr, which + // systemd keeps in the journal. Journal io.Writer // Alert is called when Open found a torn last line and added a // log_recovered entry for it, before Open returns. The broker sends an @@ -113,6 +121,7 @@ type Logger struct { journal io.Writer now func() time.Time last Anchor // the last entry; seq 0 and a zero hash when there is none + id LogID // the SHA-256 of line 1; zero while the log has no newline err error // set after a failed write, sync or journal write // found is the log_recovered entry that Open found as the last entry // of the log, if any (see LastRecovery). It never changes after Open. @@ -138,13 +147,17 @@ type Logger struct { // - It takes an exclusive flock on the open file, without waiting. If // another process holds it, such as a second broker, Open fails. // - It reads the end of the file, not the whole file, to find the last -// entry. The last complete line must be a valid entry. +// entry. The last complete line must be a valid entry. It reads line +// 1 too, for the log ID. Line 1 and the last complete line must not be +// longer than MaxLineSize. +// - It writes JournalOpenPrefix, the last entry and the log ID to +// opts.Journal. If that write fails, Open fails. // - A new or empty file: Open syncs its directory, so the new name is on // disk too. // // A torn last line: if the file does not end in a newline, the bytes after // the last newline are a torn line, such as from a power cut during a -// write. Open then writes, with one write call, a newline and a +// write. After the open line, Open writes, with one write call, a newline and a // log_recovered entry. That entry holds the length and SHA-256 of the // torn bytes. Its prev is the hash of the last complete line, so the torn // line stays outside the chain, but the entry still pins its bytes. Then @@ -222,6 +235,7 @@ func (l *Logger) start(path string, self uint32, h hooks) (Recovery, bool, error return Recovery{}, false, fmt.Errorf("audit log %s: syncing its directory: %w", path, err) } } + l.id = t.first if t.hasLast { e, bad := parseEntry(t.last) if bad != "" { @@ -233,10 +247,19 @@ func (l *Logger) start(path string, self uint32, h hooks) (Recovery, bool, error l.found = &Recovery{Seq: e.seq, TornLength: e.tornLength, TornSHA256: e.tornHash} } } + // The open line goes to the journal before any entry of this start, + // so it holds the last entry that this start found. + if _, err := io.WriteString(l.journal, JournalOpenPrefix+l.last.String()+" "+l.id.String()+"\n"); err != nil { + return Recovery{}, false, fmt.Errorf("audit log: journal: %w", err) + } if t.torn == nil { return Recovery{}, false, nil } sum := sha256.Sum256(t.torn) + if l.id.IsZero() { + // The log is one torn line: after the recovery, it is line 1. + l.id = sum + } a, err := l.append(logRecovered{TornLength: len(t.torn), TornSHA256: hex.EncodeToString(sum[:])}, true) if err != nil { return Recovery{}, false, err @@ -286,9 +309,9 @@ func checkOpenFile(fi fs.FileInfo, self uint32) error { return nil } -// readTailOf opens the log at path again, read only, to read its end. The -// file that opens must be the one that is locked, fi. It returns the size -// of the log and its end. +// readTailOf opens the log at path again, read only, to read its end and +// its line 1. The file that opens must be the one that is locked, fi. It +// returns the size of the log and its end, with the log ID. func readTailOf(path string, fi fs.FileInfo) (int64, tail, error) { r, err := os.OpenFile(path, readFlags, 0) //nolint:gosec // G304: the same path as the open log; the file must be the same file. if err != nil { @@ -303,7 +326,37 @@ func readTailOf(path string, fi fs.FileInfo) (int64, tail, error) { return 0, tail{}, errors.New("the file changed while it was opened") } t, err := readTail(r, rfi.Size()) - return rfi.Size(), t, err + if err != nil { + return 0, tail{}, err + } + if t.first, err = readFirstLine(r, rfi.Size()); err != nil { + return 0, tail{}, err + } + return rfi.Size(), t, nil +} + +// readFirstLine returns the log ID of a log of size bytes: the SHA-256 of +// its line 1, without the newline. It reads at most MaxLineSize+1 bytes. +// A log with no newline, empty or one torn line, has a zero log ID. +func readFirstLine(r io.ReaderAt, size int64) (LogID, error) { + n := min(size, MaxLineSize+1) + if n == 0 { + return LogID{}, nil + } + buf := make([]byte, n) + if _, err := r.ReadAt(buf, 0); err != nil { + return LogID{}, err + } + i := bytes.IndexByte(buf, '\n') + switch { + case i >= 0: + return sha256.Sum256(buf[:i]), nil + case n > MaxLineSize: + return LogID{}, fmt.Errorf("its first line is longer than %d bytes; "+ + "check the log with nodkey audit verify", MaxLineSize) + default: + return LogID{}, nil // no newline: readTail found one torn line + } } // tail is the end of the log. @@ -311,6 +364,7 @@ type tail struct { last []byte // the last complete line, without its newline hasLast bool // the log has a complete line torn []byte // the bytes after the last newline; nil if the log ends in a newline + first LogID // the log ID; set by readTailOf, not by readTail } // readTail reads the end of a log of size bytes. It reads at most @@ -446,8 +500,12 @@ func (l *Logger) append(ev Event, afterTorn bool) (Anchor, error) { return Anchor{}, l.fail(fmt.Errorf("audit log: sync: %w", err)) } l.last = a + if l.id.IsZero() { + // The log was empty, so this entry is line 1. + l.id = a.Hash + } // The anchor goes to the journal only when the entry is on disk. - if _, err := io.WriteString(l.journal, JournalPrefix+a.String()+"\n"); err != nil { + if _, err := io.WriteString(l.journal, JournalPrefix+a.String()+" "+l.id.String()+"\n"); err != nil { return Anchor{}, l.fail(fmt.Errorf("audit log: journal: %w", err)) } return a, nil diff --git a/internal/audit/audit_linux_test.go b/internal/audit/audit_linux_test.go index 2308a3f..b870018 100644 --- a/internal/audit/audit_linux_test.go +++ b/internal/audit/audit_linux_test.go @@ -119,15 +119,24 @@ func mustVerify(t *testing.T, path string, anchors ...Anchor) Result { return res } -// journalOf returns the journal lines for anchors. -func journalOf(anchors ...Anchor) string { +// journalOf returns the journal lines for anchors of the log id. +func journalOf(id LogID, anchors ...Anchor) string { var b strings.Builder for _, a := range anchors { - b.WriteString(JournalPrefix + a.String() + "\n") + b.WriteString(JournalPrefix + a.String() + " " + id.String() + "\n") } return b.String() } +// openLine returns the journal line that Open writes for a log with the +// last entry head and the log ID id. +func openLine(head Anchor, id LogID) string { + return JournalOpenPrefix + head.String() + " " + id.String() + "\n" +} + +// newOpenLine is the open line of a log with no line 1. +var newOpenLine = JournalOpenPrefix + "0:" + zeros + " " + zeros + "\n" + func TestAppendWritesTheChain(t *testing.T) { path := logPath(t) l := mustOpen(t, path, testHooks()) @@ -148,8 +157,9 @@ func TestAppendWritesTheChain(t *testing.T) { if res.Entries != uint64(len(anchors)) || res.Last != anchors[len(anchors)-1] { t.Errorf("Verify = %+v; want %d entries, the last %v", res, len(anchors), anchors[len(anchors)-1]) } - // The journal gets the anchors and nothing else. - if got, want := l.journal.String(), journalOf(anchors...); got != want { + // The journal gets the open line and the anchors, and nothing else. + // The log ID is the hash of line 1. + if got, want := l.journal.String(), newOpenLine+journalOf(anchors[0].Hash, anchors...); got != want { t.Errorf("journal:\n%s\nwant:\n%s", got, want) } fi, err := os.Stat(path) @@ -240,8 +250,16 @@ func TestOpenRecoversATornLine(t *testing.T) { if len(l.alerts) != 1 || l.alerts[0] != wantAlert { t.Errorf("alerts = %+v, want one: %+v", l.alerts, wantAlert) } - if got := l.journal.String(); got != journalOf(rec) { - t.Errorf("journal = %q, want %q", got, journalOf(rec)) + // The open line holds the head before the log_recovered + // entry. The log ID is the hash of line 1, which is the torn + // line if the log was only that. + id := LogID(sha256.Sum256(want.lines[0])) + wantJournal := openLine(tt.base.last, id) + journalOf(id, rec) + if len(tt.base.lines) == 0 { + wantJournal = newOpenLine + journalOf(id, rec) + } + if got := l.journal.String(); got != wantJournal { + t.Errorf("journal = %q, want %q", got, wantJournal) } if res := mustVerify(t, path, rec); res.TornLines != 1 || res.Last != rec { t.Errorf("Verify = %+v; want 1 torn line, the last entry %v", res, rec) @@ -425,7 +443,7 @@ func TestAppendFailsClosed(t *testing.T) { t.Errorf("Append after the failure: %v; want ErrBroken and %v", err, cause) } } - if got := l.journal.String(); got != journalOf(first) { + if got := l.journal.String(); got != newOpenLine+journalOf(first.Hash, first) { t.Errorf("journal = %q; want only the first entry", got) } if err := l.Close(); err != nil { @@ -449,16 +467,55 @@ func TestAppendFailsClosed(t *testing.T) { } } -// failingWriter fails every write. -type failingWriter struct{} +// failingWriter fails every write after the first ok writes. +type failingWriter struct{ ok int } -func (failingWriter) Write([]byte) (int, error) { return 0, errIO } +func (w *failingWriter) Write(p []byte) (int, error) { + if w.ok > 0 { + w.ok-- + return len(p), nil + } + return 0, errIO +} + +// TestOpenFailsWhenTheJournalFails: the open line must reach the journal. +// If it does not, Open fails, and it writes nothing to the log: not even +// the log_recovered entry of a torn line. +func TestOpenFailsWhenTheJournalFails(t *testing.T) { + base := newChain(t) + base.add(BrokerStarted{Version: "dev"}) + for _, tt := range []struct { + name string + log []byte + }{ + {"a new log", nil}, + {"a log with an entry", base.bytes()}, + {"a torn line", append(base.bytes(), half(base.lines[0])...)}, + } { + t.Run(tt.name, func(t *testing.T) { + path := logPath(t) + writeLog(t, path, tt.log, 0o600) + alerts := 0 + l, err := open(path, Options{Journal: &failingWriter{}, Alert: func(Recovery) { alerts++ }}, testHooks()) + if err == nil { + _ = l.Close() + t.Fatal("Open: no error; want a journal error") + } + if !errors.Is(err, errIO) || !strings.Contains(err.Error(), "journal") { + t.Errorf("Open: %v; want a journal error", err) + } + if got := readLog(t, path); !bytes.Equal(got, tt.log) || alerts != 0 { + t.Errorf("log after the failed Open = %q, %d alerts; want it unchanged, no alert", got, alerts) + } + }) + } +} // TestAppendFailsWhenTheJournalFails: the anchor must reach the journal. // If it does not, Append fails, and every later Append too. func TestAppendFailsWhenTheJournalFails(t *testing.T) { path := logPath(t) - l, err := open(path, Options{Journal: failingWriter{}, Alert: func(Recovery) {}}, testHooks()) + l, err := open(path, Options{Journal: &failingWriter{ok: 1}, Alert: func(Recovery) {}}, testHooks()) if err != nil { t.Fatal(err) } @@ -750,8 +807,8 @@ func TestAppendRefusesAnEvent(t *testing.T) { if res := mustVerify(t, path, a); res.Entries != 1 { t.Errorf("Verify = %+v; want 1 entry", res) } - if got := l.journal.String(); got != journalOf(a) { - t.Errorf("journal = %q, want %q", got, journalOf(a)) + if got, want := l.journal.String(), newOpenLine+journalOf(a.Hash, a); got != want { + t.Errorf("journal = %q, want %q", got, want) } } @@ -846,8 +903,8 @@ func TestAppendFromManyGoroutines(t *testing.T) { if res.Entries != goroutines*each { t.Errorf("Verify = %+v; want %d entries", res, goroutines*each) } - if lines := strings.Count(l.journal.String(), "\n"); lines != goroutines*each { - t.Errorf("journal has %d lines, want %d", lines, goroutines*each) + if lines := strings.Count(l.journal.String(), "\n"); lines != 1+goroutines*each { + t.Errorf("journal has %d lines, want %d: the open line and the anchors", lines, 1+goroutines*each) } } diff --git a/internal/audit/journal_linux_test.go b/internal/audit/journal_linux_test.go new file mode 100644 index 0000000..4b94c5f --- /dev/null +++ b/internal/audit/journal_linux_test.go @@ -0,0 +1,329 @@ +package audit + +// The open lines and the log IDs, with logs made by Open and Append, and +// changed while the broker is stopped (DESIGN.md section 9, THREAT-MODEL.md +// T17, issue #40). The journal of a test is the journal of every broker +// run, with other log lines between them: see journalCopy. + +import ( + "bytes" + "crypto/sha256" + "os" + "reflect" + "strings" + "testing" + "time" +) + +// verifyJournal checks the log at path with the journal text, like +// journalctl -o cat | nodkey audit verify. +func verifyJournal(t *testing.T, path, journal string, extra ...Anchor) (Result, error) { + t.Helper() + lines, err := ReadJournal(strings.NewReader(journal)) + if err != nil { + t.Fatalf("ReadJournal: %v", err) + } + return VerifyJournal(bytes.NewReader(readLog(t, path)), lines, extra...) +} + +func mustVerifyJournal(t *testing.T, path, journal string, extra ...Anchor) Result { + t.Helper() + res, err := verifyJournal(t, path, journal, extra...) + if err != nil { + t.Fatalf("VerifyJournal: %v", err) + } + return res +} + +// logIDOf returns the log ID of the log at path. +func logIDOf(t *testing.T, path string) LogID { + t.Helper() + first, _, _ := bytes.Cut(readLog(t, path), []byte("\n")) + return sha256.Sum256(first) +} + +// laterHooks are testHooks with a clock an hour later, so a new log has +// another line 1. +func laterHooks() hooks { + h := testHooks() + h.now = func() time.Time { return testTime.Add(time.Hour) } + return h +} + +// restart is a broker run that writes broker_started and is then killed. +func restart(t *testing.T, path string, h hooks) *testLog { + t.Helper() + l := mustOpen(t, path, h) + mustAppend(t, l, BrokerStarted{Version: "dev"}) + if err := l.Close(); err != nil { + t.Fatal(err) + } + return l +} + +// TestVerifyJournalPassesGoodRuns: a log of three runs passes, and each +// later run has an open line that is checked. +func TestVerifyJournalPassesGoodRuns(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + run2 := restart(t, path, testHooks()) + run3 := restart(t, path, testHooks()) + res := mustVerifyJournal(t, path, journalCopy(run1, run2, run3)) + want := Result{Entries: 6, Last: res.Last, Anchors: 6, LogID: logIDOf(t, path), Opens: 2, NewStarts: 1} + if !reflect.DeepEqual(res, want) { + t.Errorf("VerifyJournal = %+v, want %+v", res, want) + } +} + +// TestVerifyJournalFindsAnEntryAddedWhileStopped: a well-formed entry, +// appended while the broker is stopped, continues the chain, so every +// anchor passes (TestAnchorsMissAnEntryAddedWhileStopped). The open line +// of the next run finds it: its head is the added entry, not the last +// anchor. +func TestVerifyJournalFindsAnEntryAddedWhileStopped(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + c := newChain(t) + c.lines = bytes.Split(bytes.TrimSuffix(readLog(t, path), []byte("\n")), []byte("\n")) + c.last = Anchor{Seq: 4, Hash: sha256.Sum256(c.lines[3])} + c.add(Denied{Subject: secretsSubject(), Cause: CauseApprover}) // the added entry 5 + writeLog(t, path, c.bytes(), 0o600) + + run2 := restart(t, path, testHooks()) + journal := journalCopy(run1, run2) + if _, err := Verify(bytes.NewReader(readLog(t, path)), anchorsOf(t, journal)...); err != nil { + t.Fatalf("Verify with every anchor: %v; the anchors alone do not find it", err) + } + // Line 1 and 7 are the other log lines, 2 the open line of the new + // log, 3 to 6 the anchors of run 1, 8 the open line of run 2. + _, err := verifyJournal(t, path, journal) + checkVerifyError(t, err, 0, "journal line 8: the broker opened the log at entry 5, but the last anchor of this "+ + "log before it is entry 4: entries were added or removed while the broker was stopped") +} + +// TestVerifyJournalFindsACutLog: the log is cut while the broker is +// stopped, and the next run writes the entries again. The anchor checks +// find it first. +func TestVerifyJournalFindsACutLog(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + lines := bytes.SplitAfter(readLog(t, path), []byte("\n")) + writeLog(t, path, bytes.Join(lines[:2], nil), 0o600) + run2 := mustOpen(t, path, testHooks()) + mustAppend(t, run2, BrokerStarted{Version: "dev"}) + mustAppend(t, run2, Denied{Subject: secretsSubject(), Cause: CauseExpired}) + _, err := verifyJournal(t, path, journalCopy(run1, run2)) + checkVerifyError(t, err, 0, "two anchors for entry 3 have different hashes") + + // Cut, and nothing written again: the anchors of run 1 find it. + path = logPath(t) + run1 = firstRun(t, path) + lines = bytes.SplitAfter(readLog(t, path), []byte("\n")) + writeLog(t, path, bytes.Join(lines[:2], nil), 0o600) + run2 = mustOpen(t, path, testHooks()) + if err := run2.Close(); err != nil { + t.Fatal(err) + } + _, err = verifyJournal(t, path, journalCopy(run1, run2)) + checkVerifyError(t, err, 0, "no entry 3: the log ends at entry 2") +} + +// TestVerifyJournalShowsADeletedLog: the log is deleted while the broker +// is stopped, and the broker starts a new one at entry 1. The new log +// passes, and the result names the old log with its newest entry. +func TestVerifyJournalShowsADeletedLog(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + oldID := logIDOf(t, path) + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + run2 := restart(t, path, laterHooks()) + run3 := restart(t, path, laterHooks()) + journal := journalCopy(run1, run2, run3) + if _, err := Verify(bytes.NewReader(readLog(t, path)), anchorsOf(t, journal)...); err == nil { + t.Error("Verify with every anchor of both logs: no error") + } + res := mustVerifyJournal(t, path, journal) + want := Result{Entries: 2, Last: res.Last, Anchors: 2, LogID: logIDOf(t, path), Opens: 1, NewStarts: 2, + OtherLogs: []OtherLog{{LogID: oldID, Newest: 4}}} + if !reflect.DeepEqual(res, want) { + t.Errorf("VerifyJournal = %+v, want %+v", res, want) + } +} + +// TestVerifyJournalChecksAMovedLog: a person moves the log away on +// purpose, and the broker starts a new one. It is not a cut: each log +// passes with the same journal, and names the other one. +func TestVerifyJournalChecksAMovedLog(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + moved := path + ".1" + if err := os.Rename(path, moved); err != nil { + t.Fatal(err) + } + run2 := restart(t, path, laterHooks()) + run3 := restart(t, path, laterHooks()) + journal := journalCopy(run1, run2, run3) + oldID, newID := logIDOf(t, moved), logIDOf(t, path) + + res := mustVerifyJournal(t, path, journal) + if res.LogID != newID || res.Opens != 1 || res.Anchors != 2 || + !reflect.DeepEqual(res.OtherLogs, []OtherLog{{LogID: oldID, Newest: 4}}) { + t.Errorf("VerifyJournal of the new log = %+v", res) + } + res = mustVerifyJournal(t, moved, journal) + if res.LogID != oldID || res.Entries != 4 || res.Opens != 0 || res.Anchors != 4 || + !reflect.DeepEqual(res.OtherLogs, []OtherLog{{LogID: newID, Newest: 2}}) { + t.Errorf("VerifyJournal of the moved log = %+v", res) + } +} + +// TestVerifyJournalFindsAReplacedLog: while the broker is stopped, the log +// is replaced by another whole chain, so line 1 is new. The broker opens +// it and goes on. The journal has no anchor of that log before its open +// line. +func TestVerifyJournalFindsAReplacedLog(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + fake := newChain(t) + fake.add(BrokerStarted{Version: "made-up"}) + fake.add(Request{Subject: secretsSubject()}) + fake.add(Denied{Subject: secretsSubject(), Cause: CauseApprover}) + fake.add(BrokerStopped{}) + writeLog(t, path, fake.bytes(), 0o600) + + run2 := restart(t, path, testHooks()) + _, err := verifyJournal(t, path, journalCopy(run1, run2)) + checkVerifyError(t, err, 0, "journal line 8: the journal has no anchor of this log before the broker opened it "+ + "at entry 4: the log was replaced, or the journal lost its older lines") + // The same when the journal lost the lines of run 1. + _, err = verifyJournal(t, path, journalCopy(run2)) + checkVerifyError(t, err, 0, "journal line 2: the journal has no anchor of this log") + // And a journal of another log only names no line of this one. + other := logPath(t) + run3 := firstRun(t, other) + _, err = verifyJournal(t, path, journalCopy(run3)) + checkVerifyError(t, err, 0, "the journal has no anchor and no open line of this log") +} + +// TestVerifyJournalReadsOldAnchors: the journal of an earlier version has +// anchors without the log ID. They count as anchors of the log, for the +// anchor checks and for the open lines. +func TestVerifyJournalReadsOldAnchors(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + var oldForm strings.Builder + for _, a := range anchorsOf(t, run1.journal.String()) { + oldForm.WriteString(JournalPrefix + a.String() + "\n") + } + run2 := restart(t, path, testHooks()) + journal := "nodkey: broker started\n" + oldForm.String() + journalCopy(run2) + res := mustVerifyJournal(t, path, journal) + if res.Entries != 5 || res.Anchors != 5 || res.Opens != 1 || res.NewStarts != 0 || len(res.OtherLogs) != 0 { + t.Errorf("VerifyJournal = %+v; want 5 entries and anchors, 1 open", res) + } + // An old-form anchor of another log is taken as one of this log. + bad := Anchor{Seq: 2, Hash: sha256.Sum256([]byte("not entry 2"))} + _, err := verifyJournal(t, path, journal+JournalPrefix+bad.String()+"\n") + checkVerifyError(t, err, 0, "two anchors for entry 2 have different hashes") + // And an extra anchor too. + _, err = verifyJournal(t, path, journal, bad) + checkVerifyError(t, err, 0, "two anchors for entry 2 have different hashes") +} + +// TestVerifyJournalSkipsFalseLines: lines that are almost an anchor or an +// open line are skipped, so they can neither pass nor fail a log. +func TestVerifyJournalSkipsFalseLines(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + run2 := restart(t, path, testHooks()) + id := logIDOf(t, path) + a4 := anchorsOf(t, run1.journal.String())[3] + five := Anchor{Seq: 5, Hash: sha256.Sum256([]byte("not entry 5"))} + false1 := strings.Join([]string{ + JournalPrefix + "4:" + strings.Repeat("g", 64) + " " + id.String(), + JournalPrefix + five.String() + " " + id.String(), + JournalPrefix + five.String() + " " + id.String() + " more", + JournalPrefix + five.String() + " " + id.String() + strings.Repeat(" ", maxAnchorLine), + JournalOpenPrefix + a4.String() + " " + strings.Repeat("z", 64), + JournalOpenPrefix + "1:" + strings.Repeat("0", 64) + " " + id.String()[:63], + JournalOpenPrefix + five.String() + " " + id.String() + " ", + }, "\n") + "\n" + // Before the open line of run 2: a false open line would fail it, and + // a false anchor 5 would fail the open line of run 2. + journal := journalCopy(run1) + false1 + journalCopy(run2) + if res := mustVerifyJournal(t, path, journal); res.Opens != 1 || res.Anchors != 5 { + t.Errorf("VerifyJournal = %+v; want 1 open and 5 anchors", res) + } +} + +// TestVerifyJournalAfterATornLine: Open records a torn line. Its open line +// holds the head before the log_recovered entry, and the log passes. +func TestVerifyJournalAfterATornLine(t *testing.T) { + path := logPath(t) + run1 := firstRun(t, path) + f, err := openFile(path, os.O_WRONLY|os.O_APPEND) + if err != nil { + t.Fatal(err) + } + if _, err := f.Write([]byte(`{"seq":5,"time":"2026-`)); err != nil { + t.Fatal(err) + } + if err := f.Close(); err != nil { + t.Fatal(err) + } + run2 := restart(t, path, testHooks()) + if len(run2.alerts) != 1 || run2.alerts[0].Seq != 5 { + t.Fatalf("alerts = %+v; want the log_recovered entry 5", run2.alerts) + } + lines, err := ReadJournal(strings.NewReader(run2.journal.String())) + if err != nil || len(lines) != 3 { + t.Fatalf("ReadJournal of run 2 = %+v, %v; want an open line and two anchors", lines, err) + } + head := anchorsOf(t, run1.journal.String())[3] + if lines[0].Kind != JournalOpen || lines[0].Anchor != head || lines[0].LogID != logIDOf(t, path) { + t.Errorf("open line = %+v; want the head %v, before the log_recovered entry", lines[0], head) + } + res := mustVerifyJournal(t, path, journalCopy(run1, run2)) + if res.Entries != 6 || res.TornLines != 1 || res.Opens != 1 || res.Anchors != 6 { + t.Errorf("VerifyJournal = %+v; want 6 entries, 1 torn line, 1 open, 6 anchors", res) + } + + // A log that is only a torn line: the open line has a zero log ID, and + // the anchors have the hash of the torn bytes, which are line 1. + path = logPath(t) + writeLog(t, path, []byte(`{"seq":1,"ti`), 0o600) + run := restart(t, path, testHooks()) + if !strings.HasPrefix(run.journal.String(), newOpenLine) { + t.Errorf("journal = %q; want it to start with %q", run.journal.String(), newOpenLine) + } + res = mustVerifyJournal(t, path, journalCopy(run)) + if res.LogID != LogID(sha256.Sum256([]byte(`{"seq":1,"ti`))) || res.NewStarts != 1 || res.Anchors != 2 { + t.Errorf("VerifyJournal = %+v; want the hash of the torn bytes as the log ID", res) + } +} + +// TestOpenRefusesALongFirstLine: Open reads line 1 for the log ID; a line +// 1 longer than MaxLineSize is refused, like a long last line. +func TestOpenRefusesALongFirstLine(t *testing.T) { + c := newChain(t) + c.add(BrokerStarted{Version: "dev"}) + ok := append(c.bytes(), c.bytes()...) // two lines, so line 1 is not the last line + long := append(append(bytes.Repeat([]byte("x"), MaxLineSize+1), '\n'), bytes.Repeat(c.bytes(), 3)...) + path := logPath(t) + writeLog(t, path, long, 0o600) + if _, err := openLog(t, path, testHooks()); err == nil || !strings.Contains(err.Error(), "its first line is longer than") { + t.Errorf("Open: %v; want the long line 1 refused", err) + } + if got := readLog(t, path); !bytes.Equal(got, long) { + t.Error("Open changed the log") + } + // A line 1 of MaxLineSize bytes is fine. + edge := append(append(bytes.Repeat([]byte("x"), MaxLineSize), '\n'), ok...) + writeLog(t, path, edge, 0o600) + l := mustOpen(t, path, testHooks()) + if want := openLine(c.last, LogID(sha256.Sum256(bytes.Repeat([]byte("x"), MaxLineSize)))); l.journal.String() != want { + t.Errorf("journal = %q, want %q", l.journal.String(), want) + } +} diff --git a/internal/audit/journal_test.go b/internal/audit/journal_test.go new file mode 100644 index 0000000..f576c47 --- /dev/null +++ b/internal/audit/journal_test.go @@ -0,0 +1,124 @@ +package audit + +import ( + "bytes" + "crypto/sha256" + "errors" + "reflect" + "strings" + "testing" +) + +// TestVerifyJournal checks the open lines and the log IDs with journals +// made by hand (DESIGN.md section 9, issue #40). The tests in +// journal_linux_test.go make them with Open and Append. +func TestVerifyJournal(t *testing.T) { + c := newChain(t) + a1 := c.add(BrokerStarted{Version: "dev"}) + a2 := c.add(Request{Subject: secretsSubject()}) + a3 := c.add(BrokerStopped{}) + log := c.bytes() + id := LogID(sha256.Sum256(c.lines[0])) + other := LogID(sha256.Sum256([]byte("another log"))) + bad := Anchor{Seq: 3, Hash: sha256.Sum256([]byte("not entry 3"))} + + anchor := func(a Anchor) JournalLine { return JournalLine{Kind: JournalAnchor, Anchor: a, LogID: id} } + old := func(a Anchor) JournalLine { return JournalLine{Kind: JournalOldAnchor, Anchor: a} } + open := func(a Anchor) JournalLine { return JournalLine{Kind: JournalOpen, Anchor: a, LogID: id} } + of := func(l JournalLine, logID LogID) JournalLine { l.LogID = logID; return l } + newOpen := JournalLine{Kind: JournalOpen} + + tests := []struct { + name string + journal []JournalLine + extra []Anchor + want Result // Entries, TornLines, Last and LogID are set below + problem string // the start of the problem; "" for a pass + }{ + {name: "a new log, then a restart", + journal: []JournalLine{newOpen, anchor(a1), anchor(a2), open(a2), anchor(a3)}, + want: Result{Anchors: 3, Opens: 1, NewStarts: 1}}, + {name: "old-form anchors, then an open with the log ID", + journal: []JournalLine{old(a1), old(a2), open(a2), anchor(a3)}, + want: Result{Anchors: 3, Opens: 1}}, + {name: "an old-form anchor after new-form anchors counts as the last one", + journal: []JournalLine{anchor(a1), anchor(a2), old(a3), open(a3)}, + want: Result{Anchors: 3, Opens: 1}}, + {name: "extra anchors count like old-form anchors", journal: []JournalLine{anchor(a2)}, extra: []Anchor{a1, a3}, + want: Result{Anchors: 3}}, + {name: "a wrong extra anchor", journal: []JournalLine{anchor(a2)}, extra: []Anchor{bad}, + problem: "line 3: is entry 3, and its hash is not the hash in the anchor"}, + {name: "another log, with other hashes for the same seqs, is not checked", + journal: []JournalLine{of(newOpen, LogID{}), of(anchor(a1), other), of(anchor(bad), other), of(open(bad), other), + of(anchor(Anchor{Seq: 7, Hash: a1.Hash}), other), newOpen, anchor(a1), anchor(a2), anchor(a3)}, + want: Result{Anchors: 3, NewStarts: 2, OtherLogs: []OtherLog{{LogID: other, Newest: 7}}}}, + {name: "an anchor of another log does not count as the last one", + journal: []JournalLine{anchor(a1), anchor(a2), of(anchor(a3), other), open(a2), anchor(a3)}, + want: Result{Anchors: 3, Opens: 1, OtherLogs: []OtherLog{{LogID: other, Newest: 3}}}}, + {name: "an entry added while the broker was stopped", + journal: []JournalLine{anchor(a1), anchor(a2), {Line: 9, Kind: JournalOpen, Anchor: a3, LogID: id}}, + problem: "journal line 9: the broker opened the log at entry 3, but the last anchor of this log before it is entry 2"}, + {name: "a log cut while the broker was stopped", + journal: []JournalLine{anchor(a1), anchor(a2), anchor(a3), open(a2)}, + problem: "journal line 0: the broker opened the log at entry 2, but the last anchor of this log before it is entry 3"}, + {name: "an entry changed while the broker was stopped", + journal: []JournalLine{anchor(a1), anchor(a2), old(a3), open(bad)}, + problem: "journal line 0: the broker opened the log at entry 3, and its hash is not the hash in the anchor before it"}, + {name: "an open before any anchor of the log", + journal: []JournalLine{open(a2), anchor(a3)}, + problem: "journal line 0: the journal has no anchor of this log before the broker opened it at entry 2"}, + {name: "two anchors of the log for one entry", + journal: []JournalLine{anchor(a3), old(bad)}, + problem: "two anchors for entry 3 have different hashes"}, + {name: "an anchor of the log that does not match", + journal: []JournalLine{anchor(bad)}, + problem: "line 3: is entry 3, and its hash is not the hash in the anchor"}, + {name: "no line of the log", journal: []JournalLine{newOpen, of(anchor(a1), other)}, + problem: "the journal has no anchor and no open line of this log"}, + {name: "an empty journal", problem: "the journal has no anchor and no open line of this log"}, + {name: "only extra anchors", extra: []Anchor{a1}, + problem: "the journal has no anchor and no open line of this log"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + res, err := VerifyJournal(bytes.NewReader(log), tt.journal, tt.extra...) + if tt.problem != "" { + var ve *VerifyError + if !errors.As(err, &ve) || !strings.HasPrefix(ve.Error(), tt.problem) { + t.Fatalf("VerifyJournal = %+v, %v; want %q", res, err, tt.problem) + } + return + } + if err != nil { + t.Fatalf("VerifyJournal: %v", err) + } + want := tt.want + want.Entries, want.Last, want.LogID = 3, a3, id + if !reflect.DeepEqual(res, want) { + t.Errorf("VerifyJournal = %+v, want %+v", res, want) + } + }) + } +} + +// TestVerifyJournalFailsOnABadLog: the checks of Verify come first. +func TestVerifyJournalFailsOnABadLog(t *testing.T) { + c := newChain(t) + a1 := c.add(BrokerStarted{Version: "dev"}) + journal := []JournalLine{{Kind: JournalAnchor, Anchor: a1, LogID: sha256.Sum256(c.lines[0])}} + for _, tt := range []struct { + name, log, want string + }{ + {"empty", "", "the log is empty"}, + {"a torn line only", string(c.lines[0]), "line 1: has no newline at the end"}, + {"line 1 too long", strings.Repeat("x", MaxLineSize+1) + "\n", "line 1: is longer than"}, + } { + t.Run(tt.name, func(t *testing.T) { + _, err := VerifyJournal(strings.NewReader(tt.log), journal) + var ve *VerifyError + if !errors.As(err, &ve) || !strings.HasPrefix(ve.Error(), tt.want) { + t.Errorf("VerifyJournal: %v; want %q", err, tt.want) + } + }) + } +} diff --git a/internal/audit/verify.go b/internal/audit/verify.go index 3faed95..9bc05de 100644 --- a/internal/audit/verify.go +++ b/internal/audit/verify.go @@ -10,6 +10,7 @@ import ( "fmt" "io" "regexp" + "slices" "strconv" "strings" "time" @@ -29,6 +30,28 @@ type Result struct { // Anchors is the number of different anchors that Verify checked. // Each one matched its entry. Anchors uint64 + // LogID is the log ID of the log: the SHA-256 of its line 1. + LogID LogID + // Opens is the number of open lines of this log that VerifyJournal + // checked. Each one matched the last anchor before it. + Opens uint64 + // NewStarts is the number of open lines with a zero log ID: each is + // a start on a log with no line 1 yet, such as a new log. VerifyJournal + // does not check them. + NewStarts uint64 + // OtherLogs are the other logs that the journal names, in the order + // of their first line in the journal. VerifyJournal does not check + // them. A log that was deleted, or moved away, is one of them. + OtherLogs []OtherLog +} + +// OtherLog is a log in the journal other than the log that VerifyJournal +// checked. +type OtherLog struct { + LogID LogID + // Newest is the highest seq in the journal lines of this log: in its + // anchors and in the heads of its open lines. + Newest uint64 } // VerifyError says which line of a log failed the check, and why. It @@ -85,16 +108,122 @@ func problem(line uint64, format string, args ...uint64) *VerifyError { // without a clock battery. seq and prev prove the order, and an attacker // who can compute the chain again can fix the times too. func Verify(r io.Reader, anchors ...Anchor) (Result, error) { - v := verifier{want: make(map[uint64][sha256.Size]byte, len(anchors)), found: make(map[uint64]bool)} - for _, a := range anchors { - if a.Seq == 0 { - return Result{}, problem(0, "an anchor needs an entry number from 1") + return verify(r, func(LogID) []Anchor { return anchors }) +} + +// VerifyJournal checks a log from r, like Verify, with the lines of its +// journal from ReadJournal, in the order of the journal. extra are more +// anchors, such as from --anchor flags; they count like old-form anchors. +// The log ID of the log is the SHA-256 of its line 1. The checks after +// those of Verify: +// +// - The anchors that Verify checks are extra, the old-form anchors, and +// the anchors with the log ID. Anchors of other log IDs are of other +// logs, so they are not checked against this log. +// - Each open line with the log ID must hold the last anchor of the log +// before it in the journal (old-form anchors count as anchors of the +// log). If it does not, entries were added or changed while the +// broker was stopped. If no anchor of the log comes before it, the log +// was replaced, or the journal lost its older lines. +// - The journal must have a line of this log: an anchor or an open line. +// +// Open lines with a zero log ID are counted in Result.NewStarts, and the +// other log IDs are listed in Result.OtherLogs: a log that was deleted and +// started again at entry 1 shows up there, and so does a log that a +// person moved away. Check that log with the same journal. +func VerifyJournal(r io.Reader, journal []JournalLine, extra ...Anchor) (Result, error) { + var id LogID + res, err := verify(r, func(first LogID) []Anchor { + id = first + anchors := slices.Clone(extra) + for _, jl := range journal { + if jl.Kind == JournalOldAnchor || (jl.Kind == JournalAnchor && jl.LogID == id) { + anchors = append(anchors, jl.Anchor) + } + } + return anchors + }) + if err != nil { + return Result{}, err + } + if err := checkOpens(&res, journal); err != nil { + return Result{}, err + } + return res, nil +} + +// checkOpens makes the checks of the open lines for the log res.LogID, +// and adds what it found to res. +func checkOpens(res *Result, journal []JournalLine) error { + last := make(map[LogID]Anchor) + others := make(map[LogID]int) // the index in res.OtherLogs + seen := false // the journal has a line of this log + for _, jl := range journal { + id := jl.LogID + if jl.Kind == JournalOldAnchor { + id = res.LogID + } + if id != res.LogID { + if id.IsZero() { // an open line of a log with no line 1 + res.NewStarts++ + continue + } + i, ok := others[id] + if !ok { + i = len(res.OtherLogs) + others[id] = i + res.OtherLogs = append(res.OtherLogs, OtherLog{LogID: id}) + } + res.OtherLogs[i].Newest = max(res.OtherLogs[i].Newest, jl.Anchor.Seq) + continue + } + seen = true + if jl.Kind != JournalOpen { + last[id] = jl.Anchor + continue } - if h, ok := v.want[a.Seq]; ok && h != a.Hash { - return Result{}, problem(0, "two anchors for entry %d have different hashes: the log was cut or changed, "+ - "and the entry was written again, or the anchors come from two logs", a.Seq) + prev, ok := last[id] + switch { + case !ok: + return problem(0, "journal line %d: the journal has no anchor of this log before the broker opened it at "+ + "entry %d: the log was replaced, or the journal lost its older lines", jl.Line, jl.Anchor.Seq) + case prev.Seq != jl.Anchor.Seq: + return problem(0, "journal line %d: the broker opened the log at entry %d, but the last anchor of this log "+ + "before it is entry %d: entries were added or removed while the broker was stopped", + jl.Line, jl.Anchor.Seq, prev.Seq) + case prev.Hash != jl.Anchor.Hash: + return problem(0, "journal line %d: the broker opened the log at entry %d, and its hash is not the hash "+ + "in the anchor before it: entries were changed while the broker was stopped", jl.Line, jl.Anchor.Seq) + } + res.Opens++ + } + if !seen { + return problem(0, "the journal has no anchor and no open line of this log; check that the journal "+ + "is of this broker, and that it still has the lines since the log began") + } + return nil +} + +// verify is Verify. anchors gets the log ID, once line 1 is read, and +// returns the anchors to check. +func verify(r io.Reader, anchors func(LogID) []Anchor) (Result, error) { + v := verifier{found: make(map[uint64]bool)} + var want []Anchor + setAnchors := func(id LogID) error { + v.res.LogID = id + want = anchors(id) + v.want = make(map[uint64][sha256.Size]byte, len(want)) + for _, a := range want { + if a.Seq == 0 { + return problem(0, "an anchor needs an entry number from 1") + } + if h, ok := v.want[a.Seq]; ok && h != a.Hash { + return problem(0, "two anchors for entry %d have different hashes: the log was cut or changed, "+ + "and the entry was written again, or the anchors come from two logs", a.Seq) + } + v.want[a.Seq] = a.Hash } - v.want[a.Seq] = a.Hash + return nil } br := bufio.NewReaderSize(r, MaxLineSize+1) var no uint64 // the number of the last line read @@ -102,6 +231,13 @@ func Verify(r io.Reader, anchors ...Anchor) (Result, error) { for { raw, err := br.ReadSlice('\n') if errors.Is(err, bufio.ErrBufferFull) { + if no == 0 { + // Line 1 is too long to have a log ID: check the + // anchors alone, for the error that Verify gives. + if err := setAnchors(LogID{}); err != nil { + return Result{}, err + } + } // A line this long is not a log_recovered entry, so the line // before it is not torn: check it first. if pending != nil { @@ -117,6 +253,13 @@ func Verify(r io.Reader, anchors ...Anchor) (Result, error) { if len(raw) > 0 { no++ cur := readLine(no, raw) + if no == 1 { + // Line 1 is applied only with line 2, so the anchors are + // set before any entry is checked. + if err := setAnchors(LogID(cur.hash)); err != nil { + return Result{}, err + } + } // The role of a line depends on the next one: a line is torn // when the next line is its log_recovered entry. if pending != nil { @@ -134,12 +277,15 @@ func Verify(r io.Reader, anchors ...Anchor) (Result, error) { } } if pending == nil { + if err := setAnchors(LogID{}); err != nil { + return Result{}, err + } return Result{}, problem(0, "the log is empty") } if err := v.apply(pending); err != nil { return Result{}, err } - for _, a := range anchors { + for _, a := range want { if !v.found[a.Seq] { return Result{}, problem(0, "no entry %d: the log ends at entry %d", a.Seq, v.res.Last.Seq) } diff --git a/internal/audit/verify_test.go b/internal/audit/verify_test.go index 4b54415..e933093 100644 --- a/internal/audit/verify_test.go +++ b/internal/audit/verify_test.go @@ -6,6 +6,7 @@ import ( "encoding/hex" "errors" "io" + "reflect" "regexp" "slices" "strconv" @@ -117,8 +118,8 @@ func TestVerifyAcceptsGoodLogs(t *testing.T) { if err != nil { t.Fatalf("Verify: %v", err) } - want := Result{Entries: tt.entries, TornLines: tt.torn, Last: tt.c.last} - if res != want { + want := Result{Entries: tt.entries, TornLines: tt.torn, Last: tt.c.last, LogID: sha256.Sum256(tt.c.lines[0])} + if !reflect.DeepEqual(res, want) { t.Errorf("Verify = %+v, want %+v", res, want) } // Every entry can be an anchor, and all of them together too. diff --git a/test/e2e/e2e_test.go b/test/e2e/e2e_test.go index 7a6b02f..e9696ad 100644 --- a/test/e2e/e2e_test.go +++ b/test/e2e/e2e_test.go @@ -575,9 +575,15 @@ func (e *env) verifyAudit(t *testing.T) { p := verify("nodkey audit verify", e.auditPath) p.mustExit(t, 0) last := sha256.Sum256([]byte(lines[n-1])) + logID := sha256.Sum256([]byte(lines[0])) // the log ID is the hash of line 1 + if !strings.Contains("\n"+journal, "\naudit open ") { + t.Error("the journal has no audit open line") + } checkLines(t, "the output of nodkey audit verify", strings.TrimSuffix(p.stdout.text(), "\n"), lit("ok: "+strconv.Itoa(n)+" entries (torn lines: 0)"), lit("anchors: "+strconv.Itoa(n)+" checked, all match; the newest is entry "+strconv.Itoa(n)), + lit("log ID: "+hex.EncodeToString(logID[:])), + "^open lines: [0-9]+ checked, all match the anchor before them; new log starts: [1-9][0-9]*$", lit("last entry: "+strconv.Itoa(n)+":"+hex.EncodeToString(last[:]))) // A copy with one changed field: the client of the first request.