| 1 | package agent |
| 2 | |
| 3 | import ( |
| 4 | "bytes" |
| 5 | "fmt" |
| 6 | "io" |
| 7 | "log/slog" |
| 8 | "os" |
| 9 | "time" |
| 10 | |
| 11 | "reasonix/internal/store" |
| 12 | ) |
| 13 | |
| 14 | const ( |
| 15 | sessionDAGRotationWait = 5 * time.Second |
| 16 | sessionDAGRotationMarkerStale = 10 * time.Second |
| 17 | sessionDAGRotationPoll = 20 * time.Millisecond |
| 18 | ) |
| 19 | |
| 20 | // sessionDAGRotateBeforeReplace runs after a rotation raised its marker and |
| 21 | // before it reads late appends. Tests use it to land an unlocked append in |
| 22 | // that window; production leaves it nil. |
| 23 | var sessionDAGRotateBeforeReplace func(sessionPath string) |
| 24 | |
| 25 | // appendSessionDAGEntriesUnlocked appends one batch without the session file |
| 26 | // lock. It terminates a torn tail first so the batch starts on its own line, |
| 27 | // and re-appends when the log was rotated underneath the write, since a |
| 28 | // rotation only carries bytes it can still see in the old file. |
| 29 | func appendSessionDAGEntriesUnlocked(sessionPath string, entries []sessionDAGEntry) (int64, error) { |
| 30 | path := store.SessionEventLog(sessionPath) |
| 31 | if path == "" || len(entries) == 0 { |
| 32 | return 0, fmt.Errorf("nothing to append to session event log %q", path) |
| 33 | } |
| 34 | data, err := encodeSessionDAGEntries(entries, time.Now().UTC()) |
| 35 | if err != nil { |
| 36 | return 0, err |
| 37 | } |
| 38 | for range 3 { |
| 39 | size, moved, err := appendUnlockedOnce(sessionPath, path, data) |
| 40 | if err != nil || !moved { |
| 41 | return size, err |
| 42 | } |
| 43 | } |
| 44 | return 0, fmt.Errorf("session log %s kept rotating during an unlocked append", path) |
| 45 | } |
| 46 | |
| 47 | func appendUnlockedOnce(sessionPath, path string, data []byte) (size int64, moved bool, err error) { |
| 48 | terminated, err := logEndsWithNewline(path) |
| 49 | if err != nil { |
| 50 | return 0, false, err |
| 51 | } |
| 52 | if !terminated { |
| 53 | data = append([]byte{'\n'}, data...) |
| 54 | } |
| 55 | written, err := writeUnlockedBatch(path, data) |
| 56 | if err != nil { |
| 57 | return 0, false, err |
| 58 | } |
| 59 | // The handle is closed before waiting: a rotation publishing under us |
| 60 | // renames over the log, which Windows refuses while it is open here. |
| 61 | waitForSessionLogRotation(sessionPath) |
| 62 | current, err := os.Stat(path) |
| 63 | if err != nil { |
| 64 | return 0, false, err |
| 65 | } |
| 66 | if !os.SameFile(written, current) { |
| 67 | return 0, true, nil |
| 68 | } |
| 69 | return written.Size(), false, nil |
| 70 | } |
| 71 | |
| 72 | func writeUnlockedBatch(path string, data []byte) (os.FileInfo, error) { |
| 73 | f, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND, 0o600) |
| 74 | if err != nil { |
| 75 | return nil, fmt.Errorf("open session event log: %w", err) |
| 76 | } |
| 77 | if _, err := f.Write(data); err != nil { |
| 78 | _ = f.Close() |
| 79 | return nil, fmt.Errorf("append session entries: %w", err) |
| 80 | } |
| 81 | if err := f.Sync(); err != nil { |
| 82 | _ = f.Close() |
| 83 | return nil, err |
| 84 | } |
| 85 | written, err := f.Stat() |
| 86 | if err != nil { |
| 87 | _ = f.Close() |
| 88 | return nil, err |
| 89 | } |
| 90 | return written, f.Close() |
| 91 | } |
| 92 | |
| 93 | func logEndsWithNewline(path string) (bool, error) { |
| 94 | f, err := os.Open(path) |
| 95 | if err != nil { |
| 96 | return false, err |
| 97 | } |
| 98 | defer f.Close() |
| 99 | info, err := f.Stat() |
| 100 | if err != nil { |
| 101 | return false, err |
| 102 | } |
| 103 | if info.Size() == 0 { |
| 104 | return true, nil |
| 105 | } |
| 106 | var last [1]byte |
| 107 | if _, err := f.ReadAt(last[:], info.Size()-1); err != nil { |
| 108 | return false, err |
| 109 | } |
| 110 | return last[0] == '\n', nil |
| 111 | } |
| 112 | |
| 113 | // appendLateLinesToStaged copies the complete lines appended to the live log |
| 114 | // after the bytes a rotation consumed onto the staged replacement, so an |
| 115 | // unlocked append that landed before the rotation marker is not dropped by |
| 116 | // the atomic replace. A partial last line belongs to a writer that will |
| 117 | // re-append once the marker clears. |
| 118 | func appendLateLinesToStaged(path string, consumed int64, staged string) error { |
| 119 | f, err := os.Open(path) |
| 120 | if err != nil { |
| 121 | return err |
| 122 | } |
| 123 | defer f.Close() |
| 124 | if _, err := f.Seek(consumed, io.SeekStart); err != nil { |
| 125 | return err |
| 126 | } |
| 127 | late, err := io.ReadAll(f) |
| 128 | if err != nil { |
| 129 | return err |
| 130 | } |
| 131 | if cut := bytes.LastIndexByte(late, '\n'); cut < 0 { |
| 132 | return nil |
| 133 | } else { |
| 134 | late = late[:cut+1] |
| 135 | } |
| 136 | out, err := os.OpenFile(staged, os.O_WRONLY|os.O_APPEND, 0o600) |
| 137 | if err != nil { |
| 138 | return fmt.Errorf("carry late appends across rotation: %w", err) |
| 139 | } |
| 140 | defer out.Close() |
| 141 | if _, err := out.Write(late); err != nil { |
| 142 | return fmt.Errorf("carry late appends across rotation: %w", err) |
| 143 | } |
| 144 | if err := out.Sync(); err != nil { |
| 145 | return err |
| 146 | } |
| 147 | slog.Info("session: carried late appends across log rotation", "path", path, "bytes", len(late)) |
| 148 | return nil |
| 149 | } |
| 150 | |
| 151 | // waitForSessionLogRotation blocks while a rotation of the log is between its |
| 152 | // marker and its publish, so the SameFile check that follows an unlocked |
| 153 | // append sees the outcome of that rotation. A marker left by a crashed |
| 154 | // rotation is ignored once it is old enough. |
| 155 | func waitForSessionLogRotation(sessionPath string) { |
| 156 | marker := store.SessionEventLogRotating(sessionPath) |
| 157 | deadline := time.Now().Add(sessionDAGRotationWait) |
| 158 | for time.Now().Before(deadline) { |
| 159 | info, err := os.Stat(marker) |
| 160 | if err != nil || time.Since(info.ModTime()) > sessionDAGRotationMarkerStale { |
| 161 | return |
| 162 | } |
| 163 | time.Sleep(sessionDAGRotationPoll) |
| 164 | } |
| 165 | slog.Warn("session: rotation marker did not clear; trusting the current log", "path", sessionPath) |
| 166 | } |
| 167 |