From cc3f2f820ccc2602728012a6146eb6051682acda Mon Sep 17 00:00:00 2001 From: Mira Voss Date: Tue, 22 Sep 2026 22:56:07 +0800 Subject: [PATCH 1/7] perf(sshclient): pipeline SFTP reads for text scans A line scanner asks the SFTP layer for a few kilobytes at a time, and pkg/sftp only overlaps round trips when it is handed a buffer larger than its packet size. Every read therefore cost a full round trip: an 8 MiB window over a ~40 ms link spent 83 s median in read latency while the remote transmitted ~800 KB/s. Read through a 1 MiB read-ahead aperture with UseConcurrentReads and a bounded in-flight request count. The aperture is bounded by the caller's byte budget, so --max-scan-bytes still caps what a scan pulls from the remote file, and reads smaller than a packet (the truncation probe) still go through untouched. SFTP sessions now come from newSFTPClient, which reuses the same connection with boundary-typed errors. Median for the reported command on the reporting host drops from 83.0 s to 26.5 s (88.0/77.9 s -> 23.8/29.1 s, alternating rounds) with identical bytes and lines scanned. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- internal/sshclient/remote_state.go | 12 +- internal/sshclient/sftp_read.go | 103 +++++++++++++++ internal/sshclient/sftp_read_test.go | 189 +++++++++++++++++++++++++++ internal/sshclient/text.go | 18 ++- internal/sshclient/transport.go | 2 +- 5 files changed, 314 insertions(+), 10 deletions(-) create mode 100644 internal/sshclient/sftp_read.go create mode 100644 internal/sshclient/sftp_read_test.go diff --git a/internal/sshclient/remote_state.go b/internal/sshclient/remote_state.go index 9ce220f..21b9931 100644 --- a/internal/sshclient/remote_state.go +++ b/internal/sshclient/remote_state.go @@ -15,9 +15,9 @@ import ( // RemoteHome resolves the authenticated user's home directory through SFTP. func (c *SSHClient) RemoteHome() (string, error) { - client, err := sftp.NewClient(c.client) + client, err := c.newSFTPClient() if err != nil { - return "", fmt.Errorf("open SFTP session: %w", err) + return "", err } defer func() { _ = client.Close() }() //nolint:errcheck // best-effort close after read-only query home, err := client.RealPath(".") @@ -36,9 +36,9 @@ func (c *SSHClient) ReadRemoteFile(remotePath string, limit int64, expectedUID s if err := validateAbsoluteRemotePath(remotePath); err != nil { return nil, err } - client, clientErr := sftp.NewClient(c.client) + client, clientErr := c.newSFTPClient() if clientErr != nil { - return nil, fmt.Errorf("open SFTP session: %w", clientErr) + return nil, clientErr } defer func() { _ = client.Close() }() //nolint:errcheck // best-effort close info, statErr := client.Lstat(remotePath) @@ -127,9 +127,9 @@ func (c *SSHClient) WriteRemoteFileAtomic(remotePath string, data []byte) error if err := validateAbsoluteRemotePath(remotePath); err != nil { return err } - client, clientErr := sftp.NewClient(c.client) + client, clientErr := c.newSFTPClient() if clientErr != nil { - return fmt.Errorf("open SFTP session: %w", clientErr) + return clientErr } defer func() { _ = client.Close() }() //nolint:errcheck // best-effort close dir := path.Dir(remotePath) diff --git a/internal/sshclient/sftp_read.go b/internal/sshclient/sftp_read.go new file mode 100644 index 0000000..e3c9b03 --- /dev/null +++ b/internal/sshclient/sftp_read.go @@ -0,0 +1,103 @@ +package sshclient + +import ( + "errors" + "io" + + "github.com/pkg/sftp" +) + +// SFTP read pipelining. +// +// The SFTP protocol is request/response: every read the caller asks for costs a +// round trip unless several requests for the same file are in flight. pkg/sftp +// only overlaps round trips when it is handed a buffer larger than its 32 KiB +// packet size — see sftp.File.readAt, which splits such a read into +// maxPacket-sized requests bounded by MaxConcurrentRequestsPerFile. +// +// A line scanner asks for a few kilobytes at a time, so a plain file.Read loop +// is RTT-bound: on a ~350 ms link an 8 MiB window costs ~256 sequential round +// trips (observed: 90 s). Handing the layer 1 MiB reads keeps up to +// sftpMaxConcurrentRequests requests in flight, which turns the same window +// into ~8 waves. +const ( + // sftpReadApertureBytes is the read-ahead buffer handed to the SFTP layer. + // It is deliberately equal to sftpMaxConcurrentRequests * 32 KiB so the + // pipelining window, not the buffer, stays the limiting factor. + sftpReadApertureBytes = 1 << 20 + // sftpMinPipelinedReadBytes is the smallest caller read worth pipelining. + // Smaller reads are served straight from the source so the truncation probe + // (a single byte past --max-scan-bytes) never over-fetches. + sftpMinPipelinedReadBytes = 32 << 10 + // sftpMaxConcurrentRequests bounds in-flight SFTP requests per file. + sftpMaxConcurrentRequests = 32 +) + +// sftpClientOptions makes the pipelining window explicit instead of relying on +// package defaults, so a dependency upgrade cannot silently degrade a scan back +// to one round trip per read. +func sftpClientOptions() []sftp.ClientOption { + return []sftp.ClientOption{ + sftp.UseConcurrentReads(true), + sftp.MaxConcurrentRequestsPerFile(sftpMaxConcurrentRequests), + } +} + +// pipelinedReader reads through a read-ahead aperture so the SFTP layer can +// overlap round trips. Reads smaller than sftpMinPipelinedReadBytes bypass the +// aperture, and budget bounds how much read-ahead may ever pull, so the bytes +// offered to a caller are identical to a plain file.Read loop. +type pipelinedReader struct { + src io.Reader + buf []byte + start int + end int + budget int64 + pending error +} + +func newPipelinedReader(src io.Reader, aperture int, budget int64) *pipelinedReader { + if aperture <= 0 { + aperture = sftpReadApertureBytes + } + return &pipelinedReader{src: src, buf: make([]byte, aperture), budget: budget} +} + +func (p *pipelinedReader) Read(b []byte) (int, error) { + if p.start == p.end { + if p.pending != nil { + err := p.pending + p.pending = nil + return 0, err + } + if len(b) < sftpMinPipelinedReadBytes || p.budget <= 0 { + return p.src.Read(b) + } + if err := p.fill(); err != nil { + return 0, err + } + } + n := copy(b, p.buf[p.start:p.end]) + p.start += n + return n, nil +} + +// fill tops the aperture up from the source. Bytes already buffered are served +// before any deferred error, matching io.Reader semantics. +func (p *pipelinedReader) fill() error { + want := int64(len(p.buf)) + if p.budget < want { + want = p.budget + } + n, err := p.src.Read(p.buf[:want]) + p.start, p.end = 0, n + p.budget -= int64(n) + if n > 0 { + p.pending = err + return nil + } + if errors.Is(err, io.EOF) { + return io.EOF + } + return err +} diff --git a/internal/sshclient/sftp_read_test.go b/internal/sshclient/sftp_read_test.go new file mode 100644 index 0000000..3461cdc --- /dev/null +++ b/internal/sshclient/sftp_read_test.go @@ -0,0 +1,189 @@ +package sshclient + +import ( + "bytes" + "io" + "testing" +) + +// recordingReader counts how many bytes were pulled from the source and the +// size of each request, which is what the pipelining window depends on. +type recordingReader struct { + data []byte + pos int + pulls int + pullMax int +} + +func (r *recordingReader) Read(p []byte) (int, error) { + if r.pos >= len(r.data) { + return 0, io.EOF + } + n := copy(p, r.data[r.pos:]) + r.pos += n + r.pulls++ + if n > r.pullMax { + r.pullMax = n + } + return n, nil +} + +// TestPipelinedReaderServesSameBytes feeds the same source through the +// pipelined reader and compares with the original: the bytes and the EOF +// position must match exactly, otherwise read-ahead would change scan results. +func TestPipelinedReaderServesSameBytes(t *testing.T) { + source := make([]byte, 3*(1<<20)+12345) + for i := range source { + source[i] = byte(i % 251) + } + + pr := newPipelinedReader(&recordingReader{data: source}, 1<<20, int64(len(source))) + var got bytes.Buffer + buf := make([]byte, 64<<10) + for { + n, err := pr.Read(buf) + got.Write(buf[:n]) + if err == io.EOF { + break + } + if err != nil { + t.Fatalf("read failed: %v", err) + } + } + if !bytes.Equal(got.Bytes(), source) { + t.Fatalf("pipelined reader returned %d bytes differing from the source", got.Len()) + } +} + +// TestPipelinedReaderSmallReadsBypassAperture pins the truncation-probe +// guarantee: a caller read below the pipelining threshold must pull exactly +// what it asked for, never a read-ahead block. +func TestPipelinedReaderSmallReadsBypassAperture(t *testing.T) { + src := &recordingReader{data: make([]byte, 1<<20)} + pr := newPipelinedReader(src, 1<<20, 1<<20) + + one := make([]byte, 1) + if _, err := pr.Read(one); err != nil { + t.Fatalf("read failed: %v", err) + } + if src.pos != 1 { + t.Fatalf("1-byte read pulled %d bytes from the source, want 1", src.pos) + } + + two := make([]byte, 4096) + if _, err := pr.Read(two); err != nil { + t.Fatalf("read failed: %v", err) + } + if src.pos != 1+len(two) { + t.Fatalf("4 KiB read pulled %d bytes total, want %d", src.pos, 1+len(two)) + } +} + +// TestPipelinedReaderLargeReadsUseAperture verifies the read-ahead path is +// actually taken, and that its requests are aperture-sized rather than +// line-sized, which is what lets pkg/sftp overlap round trips. +func TestPipelinedReaderLargeReadsUseAperture(t *testing.T) { + const aperture = 1 << 20 + src := &recordingReader{data: make([]byte, 5<<20)} + pr := newPipelinedReader(src, aperture, 5<<20) + + buf := make([]byte, 64<<10) + if _, err := pr.Read(buf); err != nil { + t.Fatalf("read failed: %v", err) + } + if src.pulls != 1 { + t.Fatalf("source pulled %d times, want a single read-ahead", src.pulls) + } + if src.pullMax != aperture { + t.Fatalf("read-ahead was %d bytes, want the %d-byte aperture", src.pullMax, aperture) + } + // The caller asked for 64 KiB and got it from the aperture. + if src.pos != aperture { + t.Fatalf("source advanced to %d, want %d", src.pos, aperture) + } +} + +// TestPipelinedReaderBudgetBoundsReadAhead is the --max-scan-bytes guard: the +// read-ahead may never pull past the window budget, so a scan cannot fetch +// remote bytes the caller was not allowed to read. +func TestPipelinedReaderBudgetBoundsReadAhead(t *testing.T) { + const budget = 2 << 20 + src := &recordingReader{data: make([]byte, 8<<20)} + pr := newPipelinedReader(src, 1<<20, budget) + + remaining := int64(budget) + buf := make([]byte, 64<<10) + for remaining > 0 { + want := int64(len(buf)) + if remaining < want { + want = remaining + } + n, err := pr.Read(buf[:want]) + if err != nil { + t.Fatalf("read failed: %v", err) + } + remaining -= int64(n) + } + if int64(src.pos) != budget { + t.Fatalf("source advanced to %d after the budget was consumed, want %d", src.pos, budget) + } + + // Past the budget the reader serves the caller directly, which is how the + // truncation probe sees one byte beyond --max-scan-bytes and no more. + if _, err := pr.Read(buf[:64<<10]); err != nil { + t.Fatalf("read past budget failed: %v", err) + } + if src.pos != budget+(64<<10) { + t.Fatalf("read past the budget pulled %d bytes, want %d", src.pos, budget+(64<<10)) + } +} + +// TestPipelinedReaderPreservesFinalPartialRead covers a source that returns +// data and io.EOF together: the bytes must be delivered before the error. +func TestPipelinedReaderPreservesFinalPartialRead(t *testing.T) { + pr := newPipelinedReader(&eofWithDataReader{data: []byte("tail-bytes")}, 64<<10, 1<<20) + + var got bytes.Buffer + buf := make([]byte, 64<<10) + for { + n, err := pr.Read(buf) + got.Write(buf[:n]) + if err == io.EOF { + break + } + if err != nil { + t.Fatalf("read failed: %v", err) + } + } + if got.String() != "tail-bytes" { + t.Fatalf("got %q, want %q", got.String(), "tail-bytes") + } +} + +type eofWithDataReader struct { + data []byte + done bool +} + +func (r *eofWithDataReader) Read(p []byte) (int, error) { + if r.done { + return 0, io.EOF + } + r.done = true + return copy(p, r.data), io.EOF +} + +// TestSFTPClientOptionsEnablePipelining guards the dependency-dependent part of +// the fix: the options that keep pkg/sftp overlapping reads must stay wired. +func TestSFTPClientOptionsEnablePipelining(t *testing.T) { + opts := sftpClientOptions() + if len(opts) != 2 { + t.Fatalf("sftpClientOptions returned %d options, want 2 (UseConcurrentReads + MaxConcurrentRequestsPerFile)", len(opts)) + } + if sftpMaxConcurrentRequests <= 1 { + t.Fatalf("sftpMaxConcurrentRequests = %d, want a pipelining window", sftpMaxConcurrentRequests) + } + if sftpReadApertureBytes < sftpMaxConcurrentRequests<<10 { + t.Fatalf("aperture %d cannot keep %d requests in flight", sftpReadApertureBytes, sftpMaxConcurrentRequests) + } +} diff --git a/internal/sshclient/text.go b/internal/sshclient/text.go index a8776cb..1e07d33 100644 --- a/internal/sshclient/text.go +++ b/internal/sshclient/text.go @@ -28,9 +28,9 @@ func (c *SSHClient) OpenRemoteText(remotePath string, fromEnd bool, maxBytes int if maxBytes <= 0 { maxBytes = 8 << 20 } - client, err := sftp.NewClient(c.client) + client, err := c.newSFTPClient() if err != nil { - return nil, meta, fmt.Errorf("open SFTP session: %w", err) + return nil, meta, err } info, statErr := client.Lstat(remotePath) if statErr != nil { @@ -56,14 +56,26 @@ func (c *SSHClient) OpenRemoteText(remotePath string, fromEnd bool, maxBytes int } meta.SkipPartial = true } - return &sftpReadCloser{File: file, session: client}, meta, nil + // maxBytes bounds read-ahead too: a scan never pulls more than its window + // from the remote file, except for the single probe byte that detects + // --max-scan-bytes truncation. + return &sftpReadCloser{ + reader: newPipelinedReader(file, sftpReadApertureBytes, maxBytes), + File: file, + session: client, + }, meta, nil } type sftpReadCloser struct { + reader io.Reader *sftp.File session *sftp.Client } +func (f *sftpReadCloser) Read(p []byte) (int, error) { + return f.reader.Read(p) +} + func (f *sftpReadCloser) Close() error { fileErr := f.File.Close() sessErr := f.session.Close() diff --git a/internal/sshclient/transport.go b/internal/sshclient/transport.go index 0166dec..82276bb 100644 --- a/internal/sshclient/transport.go +++ b/internal/sshclient/transport.go @@ -91,7 +91,7 @@ func (c *SSHClient) newSFTPClient() (*sftp.Client, error) { if err != nil { return nil, err } - client, err := sftp.NewClient(conn) + client, err := sftp.NewClient(conn, sftpClientOptions()...) if err != nil { return nil, c.transportError("remote_io", "open SFTP session", err) } From 6a354208fd4a3b2835abc7b9de16b1e92621370c Mon Sep 17 00:00:00 2001 From: Mira Voss Date: Tue, 22 Sep 2026 22:56:14 +0800 Subject: [PATCH 2/7] feat(app): narrate sshx text scans on stderr A wide window over a slow link produced no output for a minute or more, so callers timing out at 30 s could not tell a slow scan from a hang, and a scan that stopped at its byte budget returned partial results without saying so. Narrate progress on stderr after a 3 s grace period, at most once per second, with bytes, percentage, lines, elapsed and matches. A scan that stops at --max-scan-bytes warns that its results are partial and names --offset/--tail/--pattern/--max-scan-bytes as the ways to narrow it; a slow scan closes with the same advice. Truncation reasons are a joined list ("max_scan_bytes,max_hits"), so the warning tests membership instead of string equality. stats gains expected_scan_bytes, the byte budget of the window, so a caller can size a scan and spot a partial one before trusting total_hits_exact. The field is additive and omitted for journal scans. stdout still carries exactly one sshx.text.v1 document: progress and advice are stderr-only. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/text.md | 36 ++++ internal/app/text.go | 35 ++- internal/app/text_progress.go | 121 +++++++++++ internal/app/text_progress_test.go | 274 ++++++++++++++++++++++++ internal/textsafe/help.go | 2 +- internal/textsafe/scan.go | 77 ++++++- internal/textsafe/scan_progress_test.go | 147 +++++++++++++ internal/textsafe/types.go | 22 ++ 8 files changed, 695 insertions(+), 19 deletions(-) create mode 100644 internal/app/text_progress.go create mode 100644 internal/app/text_progress_test.go create mode 100644 internal/textsafe/scan_progress_test.go diff --git a/docs/text.md b/docs/text.md index 6b3d6fc..914a2c4 100644 --- a/docs/text.md +++ b/docs/text.md @@ -37,3 +37,39 @@ JSON schema `sshx.text.v1`. Branch on `success`, `hits[].kind`, `stats.total_hits` vs `stats.returned`, `truncated`, `truncated_reason`, `redacted`, and `line_origin` (`file` or `scanned_window`). Secret-shaped spans are redacted unless `--no-redact`. Audit events omit hit text. + +`stats` also carries the window accounting a caller needs to judge coverage: + +| Field | Meaning | +| --------------------- | ---------------------------------------------------------------- | +| `file_size` | Remote file size when the source is a file (omitted for journal) | +| `window_start_byte` | First byte the window reads | +| `expected_scan_bytes` | Window budget: the window capped by `--max-scan-bytes` | + +`expected_scan_bytes` is additive and omitted when the source size is unknown +(journal). Compare it with `bytes_scanned`: a scan that stopped early reports +less than it expected, and a scan that hit its budget sets +`truncated_reason=max_scan_bytes` with `total_hits_exact=false`. + +## Monitoring + +A wide window over a slow link used to look like a hang. `sshx text` now +narrates progress on **stderr** while it scans: + +```text +sshx text: scanning 2.0MiB/2097152B of 61.3MiB/64296766B (3%) lines=10240 elapsed=4.1s matches=0 +sshx text: warning: scan stopped at its --max-scan-bytes budget after 12.0s (8.0MiB/8388608B scanned, 8.0MiB/8388608B in window); results are partial (total_hits_exact=false). Narrow with --offset=N or --tail=N, pre-filter with --pattern=..., or raise --max-scan-bytes=N. +``` + +- Progress appears only after a grace period, at most once per second, and + never for a scan that finishes quickly. +- A scan that stops at its byte budget always warns, so partial results are + never mistaken for complete ones. A slow scan closes with the same + `--offset`/`--tail` advice. +- **stdout stays exactly one JSON document.** Progress and advice go to stderr + only, so `--json` parsing is unaffected. + +```bash +# Narrow the window instead of scanning 8MiB to answer a small question +sshx text -h=prod-web --path=/var/log/app.log --offset=41000 --limit=200 --json +``` diff --git a/internal/app/text.go b/internal/app/text.go index c3c9a9e..663b134 100644 --- a/internal/app/text.go +++ b/internal/app/text.go @@ -2,6 +2,7 @@ package app import ( "fmt" + "os" "strings" "time" @@ -43,13 +44,15 @@ type textJSONResult struct { } type textRun struct { - config *sshclient.Config - audit *auditRecorder - start time.Time - phase string - client *sshclient.SSHClient - req textsafe.Request - scan textsafe.Result + config *sshclient.Config + audit *auditRecorder + start time.Time + phase string + client *sshclient.SSHClient + req textsafe.Request + scan textsafe.Result + reporter *textScanReporter + scanStart time.Time } func textRequestFrom(config *sshclient.Config) (textsafe.Request, error) { @@ -155,6 +158,11 @@ func HandleText(config *sshclient.Config, audit *auditRecorder) (err error) { } func (r *textRun) collect(req textsafe.Request) (textsafe.Result, error) { + // A streamed SFTP window is the only source that can idle for minutes, so it + // is the one that narrates progress. stdout stays untouched because the + // reporter writes to stderr. + r.reporter = newTextScanReporter(os.Stderr, req.Pattern != "") + r.scanStart = time.Now() switch req.Kind { case textsafe.SourceFile: if r.config.TextUseSudo { @@ -178,7 +186,7 @@ func (r *textRun) scanSFTP(req textsafe.Request) (textsafe.Result, error) { req.FileSize = meta.Size req.WindowStartByte = meta.StartByte req.SkipPartialFirst = meta.SkipPartial - return textsafe.Scan(file, req) + return textsafe.ScanWithProgress(file, req, r.reporter) } func (r *textRun) scanPrivilegedFile(req textsafe.Request) (textsafe.Result, error) { @@ -220,6 +228,7 @@ func (r *textRun) succeed() error { r.phase = "complete" r.recordAudit(0, "", nil) result := r.baseResult(true, 0, "", nil) + r.reportScanAdvice() if r.config.JSONOutput { return emitTextJSON(r.config, result) } @@ -230,6 +239,16 @@ func (r *textRun) succeed() error { return nil } +// reportScanAdvice closes a streamed scan with the guidance a caller needs when +// the window was too wide or the scan stopped at its byte budget. It writes to +// stderr only. +func (r *textRun) reportScanAdvice() { + if r.reporter == nil { + return + } + r.reporter.Finish(r.scan, time.Since(r.scanStart)) +} + func (r *textRun) fail(kind string, failErr error) error { r.recordAudit(-1, kind, failErr) result := r.baseResult(false, -1, kind, failErr) diff --git a/internal/app/text_progress.go b/internal/app/text_progress.go new file mode 100644 index 0000000..0d8a4a2 --- /dev/null +++ b/internal/app/text_progress.go @@ -0,0 +1,121 @@ +package app + +import ( + "fmt" + "io" + "time" + + "github.com/talkincode/sshx/internal/textsafe" +) + +// Long remote scans used to look like a hang: a 90 s SFTP window produced no +// output at all. The reporter narrates progress on stderr, which keeps stdout a +// single machine-readable JSON document for --json callers. +const ( + // textProgressGrace hides progress for quick scans. + textProgressGrace = 3 * time.Second + // textProgressInterval limits progress lines to one per second. + textProgressInterval = time.Second + // textSlowScanAdvice is the elapsed scan time worth advising the caller to + // narrow the window. + textSlowScanAdvice = 10 * time.Second +) + +// textScanReporter writes bounded scan progress and closing advice to a single +// stream (stderr in production). +type textScanReporter struct { + out io.Writer + pattern bool + start time.Time + lastLine time.Time + sample textsafe.ScanProgress + + grace time.Duration + interval time.Duration + advice time.Duration +} + +func newTextScanReporter(out io.Writer, patternSet bool) *textScanReporter { + return &textScanReporter{ + out: out, + pattern: patternSet, + start: time.Now(), + grace: textProgressGrace, + interval: textProgressInterval, + advice: textSlowScanAdvice, + } +} + +// Progress implements textsafe.ProgressObserver. +func (r *textScanReporter) Progress(p textsafe.ScanProgress) { + r.sample = p + now := time.Now() + if now.Sub(r.start) < r.grace { + return + } + if !r.lastLine.IsZero() && now.Sub(r.lastLine) < r.interval { + return + } + r.lastLine = now + fmt.Fprintln(r.out, r.progressLine(now)) +} + +func (r *textScanReporter) progressLine(now time.Time) string { + p := r.sample + line := fmt.Sprintf("sshx text: scanning %s", formatByteCount(p.Bytes)) + if p.FileSize > 0 { + line += fmt.Sprintf(" of %s (%d%%)", formatByteCount(p.FileSize), percentOf(p.Bytes, p.FileSize)) + } + line += fmt.Sprintf(" lines=%d elapsed=%s", p.Lines, formatSeconds(now.Sub(r.start))) + if r.pattern { + line += fmt.Sprintf(" matches=%d", p.MatchedLines) + } + return line +} + +// Finish prints advice when a scan was slow or stopped at its byte budget, so +// partial results are never silently mistaken for complete ones. +func (r *textScanReporter) Finish(result textsafe.Result, elapsed time.Duration) { + if r.out == nil { + return + } + if result.Truncated && textsafe.HasTruncationReason(result.TruncatedReason, "max_scan_bytes") { + fmt.Fprintf(r.out, "sshx text: warning: scan stopped at its --max-scan-bytes budget after %s (%s scanned, %s in window); results are partial "+ + "(total_hits_exact=false). Narrow with --offset=N or --tail=N, pre-filter with --pattern=..., or raise --max-scan-bytes=N.\n", + formatSeconds(elapsed), formatByteCount(result.Stats.BytesScanned), formatByteCount(result.Stats.ExpectedScanBytes)) + return + } + if elapsed >= r.advice { + fmt.Fprintf(r.out, "sshx text: notice: scan took %s for %s; narrow the window with --offset=N or --tail=N when a smaller window answers the question.\n", + formatSeconds(elapsed), formatByteCount(result.Stats.BytesScanned)) + } +} + +// formatByteCount renders a byte count as an exact integer with a binary unit. +func formatByteCount(n int64) string { + switch { + case n >= 1<<30: + return fmt.Sprintf("%.1fGiB/%dB", float64(n)/(1<<30), n) + case n >= 1<<20: + return fmt.Sprintf("%.1fMiB/%dB", float64(n)/(1<<20), n) + case n >= 1<<10: + return fmt.Sprintf("%.1fKiB/%dB", float64(n)/(1<<10), n) + default: + return fmt.Sprintf("%dB", n) + } +} + +func percentOf(part, whole int64) int { + if whole <= 0 { + return 0 + } + pct := part * 100 / whole + if pct > 100 { + return 100 + } + return int(pct) +} + +func formatSeconds(d time.Duration) string { + return fmt.Sprintf("%.1fs", d.Seconds()) +} diff --git a/internal/app/text_progress_test.go b/internal/app/text_progress_test.go new file mode 100644 index 0000000..22a6a01 --- /dev/null +++ b/internal/app/text_progress_test.go @@ -0,0 +1,274 @@ +package app + +import ( + "bytes" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/talkincode/sshx/internal/execution" + "github.com/talkincode/sshx/internal/textsafe" +) + +func newTestReporter(out *bytes.Buffer, patternSet bool) *textScanReporter { + r := newTextScanReporter(out, patternSet) + r.grace = 0 + r.interval = 0 + r.advice = time.Hour + return r +} + +// TestTextScanReporterStaysQuietDuringGrace: a fast scan must not print +// anything, so ordinary runs keep their output unchanged. +func TestTextScanReporterStaysQuietDuringGrace(t *testing.T) { + var out bytes.Buffer + reporter := newTextScanReporter(&out, true) + reporter.Progress(textsafe.ScanProgress{Bytes: 4096, Lines: 10, FileSize: 1 << 20}) + assert.Empty(t, out.String()) +} + +// TestTextScanReporterPrintsBoundedProgress covers the monitored shape: one +// line per interval with bytes, percentage, lines, elapsed, and matches. +func TestTextScanReporterPrintsBoundedProgress(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, true) + reporter.interval = time.Hour // only the first sample may print + + reporter.Progress(textsafe.ScanProgress{Bytes: 512 << 10, Lines: 2048, MatchedLines: 7, FileSize: 2 << 20}) + + lines := strings.Split(strings.TrimRight(out.String(), "\n"), "\n") + require.Len(t, lines, 1, "progress must be throttled to one line per interval") + assert.Contains(t, lines[0], "sshx text: scanning") + assert.Contains(t, lines[0], "512.0KiB/524288B") + assert.Contains(t, lines[0], " of 2.0MiB/2097152B") + assert.Contains(t, lines[0], "(25%)") + assert.Contains(t, lines[0], "lines=2048") + assert.Contains(t, lines[0], "matches=7") + + reporter.Progress(textsafe.ScanProgress{Bytes: 1 << 20, Lines: 4096, FileSize: 2 << 20}) + assert.Len(t, strings.Split(strings.TrimRight(out.String(), "\n"), "\n"), 1) +} + +// TestTextScanReporterOmitsMatchesWithoutPattern keeps the line honest for a +// preset-only scan, where no match count exists. +func TestTextScanReporterOmitsMatchesWithoutPattern(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.Progress(textsafe.ScanProgress{Bytes: 1 << 20, Lines: 10, FileSize: 1 << 20}) + assert.NotContains(t, out.String(), "matches=") + assert.Contains(t, out.String(), "(100%)") +} + +// TestTextScanReporterUnknownSizeOmitsPercentage: a journal scan has no file +// size, so progress must not invent a percentage. +func TestTextScanReporterUnknownSizeOmitsPercentage(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.Progress(textsafe.ScanProgress{Bytes: 1 << 20, Lines: 10}) + assert.NotContains(t, out.String(), "%") + assert.Contains(t, out.String(), "1.0MiB/1048576B") +} + +// TestTextScanReporterWarnsOnByteBudgetTruncation is the "partial results" +// guard: stopping at --max-scan-bytes must say so and name the narrower +// alternatives. +func TestTextScanReporterWarnsOnByteBudgetTruncation(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.Finish(textsafe.Result{ + Truncated: true, + TruncatedReason: "max_scan_bytes", + Stats: textsafe.Stats{BytesScanned: 1 << 20, ExpectedScanBytes: 1 << 20}, + }, 4*time.Second) + + line := out.String() + assert.Contains(t, line, "warning") + assert.Contains(t, line, "--max-scan-bytes") + assert.Contains(t, line, "--offset") + assert.Contains(t, line, "--tail") + assert.Contains(t, line, "partial") + assert.Contains(t, line, "total_hits_exact=false") +} + +// TestTextScanReporterWarnsWhenReasonsAreJoined guards the multi-reason form of +// truncated_reason: a scan that also capped its hit list reports +// "max_scan_bytes,max_hits", and the byte-budget warning must still appear. +func TestTextScanReporterWarnsWhenReasonsAreJoined(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.Finish(textsafe.Result{ + Truncated: true, + TruncatedReason: "max_scan_bytes,max_hits", + Stats: textsafe.Stats{BytesScanned: 1 << 20, ExpectedScanBytes: 1 << 20}, + }, 4*time.Second) + + assert.Contains(t, out.String(), "warning") + assert.Contains(t, out.String(), "--max-scan-bytes") +} + +// TestTextScanReporterSkipsOtherTruncationReasons: a capped hit list is not a +// bounded scan, so it must not claim the window was cut short. +func TestTextScanReporterSkipsOtherTruncationReasons(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.Finish(textsafe.Result{ + Truncated: true, + TruncatedReason: "max_hits", + Stats: textsafe.Stats{BytesScanned: 1 << 20, ExpectedScanBytes: 1 << 20}, + }, 4*time.Second) + + assert.NotContains(t, out.String(), "warning") +} + +// TestTextScanReporterAdvisesOnSlowScan covers the second trigger: a scan that +// covered its window but took long enough that a smaller window is worth +// suggesting next time. +func TestTextScanReporterAdvisesOnSlowScan(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.advice = time.Second + reporter.Finish(textsafe.Result{Stats: textsafe.Stats{BytesScanned: 8 << 20}}, 12*time.Second) + + line := out.String() + assert.Contains(t, line, "notice") + assert.Contains(t, line, "8.0MiB/8388608B") + assert.Contains(t, line, "--offset") +} + +// TestTextScanReporterQuietOnFastCompleteScan: no warning, no notice. +func TestTextScanReporterQuietOnFastCompleteScan(t *testing.T) { + var out bytes.Buffer + reporter := newTestReporter(&out, false) + reporter.advice = time.Minute + reporter.Finish(textsafe.Result{Stats: textsafe.Stats{BytesScanned: 4096}}, 10*time.Millisecond) + assert.Empty(t, out.String()) +} + +func TestTextProgressFormatters(t *testing.T) { + assert.Equal(t, "512B", formatByteCount(512)) + assert.Equal(t, "1.5KiB/1536B", formatByteCount(1536)) + assert.Equal(t, "1.5MiB/1572864B", formatByteCount(1536<<10)) + assert.Equal(t, "2.0GiB/2147483648B", formatByteCount(2<<30)) + assert.Equal(t, 50, percentOf(1<<20, 2<<20)) + assert.Equal(t, 100, percentOf(9<<20, 2<<20)) + assert.Equal(t, 0, percentOf(10, 0)) + assert.Equal(t, "1.5s", formatSeconds(1500*time.Millisecond)) +} + +// TestReportSudoPromptFailureExplainsTheBoundary: when the remote refuses for +// want of a password that auto-fill never supplies, the run must say why. +func TestReportSudoPromptFailureExplainsTheBoundary(t *testing.T) { + tests := []struct { + name string + command string + output string + want bool + }{ + { + name: "mid-command sudo refused", + command: `cd /data/appdata/teamsacs && sudo docker compose up -d`, + output: "sudo: a password is required\n", + want: true, + }, + { + name: "leading sudo is auto-filled", + command: `sudo docker compose up -d`, + output: "sudo: a password is required\n", + want: false, + }, + { + name: "mid-command sudo succeeded", + command: `cd /srv && sudo systemctl restart api`, + output: "", + want: false, + }, + { + name: "unrelated failure", + command: `cd /srv && sudo systemctl restart api`, + output: "bash: systemctl: command not found\n", + want: false, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + var out bytes.Buffer + reportSudoPromptFailure(&out, tc.command, tc.output) + if !tc.want { + assert.Empty(t, out.String()) + return + } + assert.Contains(t, out.String(), "sudo is not the first token") + assert.Contains(t, out.String(), `sudo sh -c`) + }) + } +} + +func TestReportRunSudoPromptFailuresPerTarget(t *testing.T) { + command := `cd /data/appdata/teamsacs && sudo docker compose up -d` + outcome := execution.RunOutcome{ + RunID: "run-test", + Results: []execution.TargetResult{ + { + Target: execution.ResolvedTarget{Alias: "prod-web", Address: "192.0.2.10"}, + Stderr: "sudo: a password is required\n", + }, + { + Target: execution.ResolvedTarget{Alias: "prod-edge", Address: "192.0.2.11"}, + Stderr: "container started\n", + }, + }, + } + + _, stderr := captureStreams(t, func() { + reportRunSudoPromptFailures(outcome, command) + }) + + // Only the target that actually hit the prompt is named. + assert.Contains(t, string(stderr), "[prod-web]") + assert.NotContains(t, string(stderr), "[prod-edge]") + assert.Contains(t, string(stderr), "sudo is not the first token") +} + +func TestReportRunSudoPromptFailuresStaysQuiet(t *testing.T) { + refusal := execution.RunOutcome{ + RunID: "run-test", + Results: []execution.TargetResult{{ + Target: execution.ResolvedTarget{Alias: "prod-web"}, + Stderr: "sudo: a password is required\n", + }}, + } + + tests := []struct { + name string + outcome execution.RunOutcome + command string + }{ + {name: "leading sudo is auto-filled", outcome: refusal, command: `sudo docker compose up -d`}, + {name: "no sudo at all", outcome: refusal, command: `docker compose ps`}, + { + name: "no sudo prompt in the output", + outcome: execution.RunOutcome{ + RunID: "run-test", + Results: []execution.TargetResult{{ + Target: execution.ResolvedTarget{Alias: "prod-web"}, + Stderr: "bash: docker: command not found\n", + }}, + }, + command: `cd /srv && sudo docker compose up -d`, + }, + {name: "no targets ran", outcome: execution.RunOutcome{RunID: "run-test"}, command: `cd /srv && sudo id`}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + _, stderr := captureStreams(t, func() { + reportRunSudoPromptFailures(tc.outcome, tc.command) + }) + assert.Empty(t, string(stderr)) + }) + } +} diff --git a/internal/textsafe/help.go b/internal/textsafe/help.go index 8ffc683..2630c24 100644 --- a/internal/textsafe/help.go +++ b/internal/textsafe/help.go @@ -58,7 +58,7 @@ func Help() HelpDocument { Bounds: []HelpFlag{ {Flag: "--max-hits=N", Description: "Returned hits cap (default 20). stats.total_hits may be larger."}, {Flag: "--max-bytes=N", Description: "Returned hit text cap (default 64KiB)."}, - {Flag: "--max-scan-bytes=N", Description: "Remote bytes scanned (default 8MiB)."}, + {Flag: "--max-scan-bytes=N", Description: "Remote bytes scanned (default 8MiB). A scan that stops here warns on stderr and sets truncated_reason=max_scan_bytes; stats.expected_scan_bytes reports the window budget so a caller can size a scan before trusting total_hits_exact."}, {Flag: "--no-redact", Description: "Keep secret-shaped spans. Default redacts password=/token=/bearer/JWT."}, }, Presets: []HelpPreset{ diff --git a/internal/textsafe/scan.go b/internal/textsafe/scan.go index b58cfa5..dc3b83f 100644 --- a/internal/textsafe/scan.go +++ b/internal/textsafe/scan.go @@ -43,6 +43,12 @@ type openBlock struct { // Scan reads r once and returns bounded, classified hits. func Scan(r io.Reader, req Request) (Result, error) { + return ScanWithProgress(r, req, nil) +} + +// ScanWithProgress is Scan with bounded progress samples. The observer must not +// block and must not write to stdout. +func ScanWithProgress(r io.Reader, req Request, observer ProgressObserver) (Result, error) { if err := req.Normalize(); err != nil { return Result{}, err } @@ -61,11 +67,13 @@ func Scan(r io.Reader, req Request) (Result, error) { scanner.Buffer(buf, MaxLineBytes) var ( - lines []lineRec - n int - skipped bool - probe []byte - truncated string + lines []lineRec + n int + skipped bool + probe []byte + truncated string + matchedLines int + lastSampleBytes int64 ) for scanner.Scan() { raw := scanner.Bytes() @@ -86,6 +94,18 @@ func Scan(r io.Reader, req Request) (Result, error) { continue } n++ + if observer != nil && pattern != nil && pattern.Match(raw) { + matchedLines++ + } + if observer != nil && (n%progressSampleLines == 0 || limited.n-lastSampleBytes >= progressSampleBytes) { + lastSampleBytes = limited.n + observer.Progress(ScanProgress{ + Bytes: limited.n, + Lines: n, + MatchedLines: matchedLines, + FileSize: req.FileSize, + }) + } text := string(raw) if !utf8.ValidString(text) { text = strings.ToValidUTF8(text, "\uFFFD") @@ -132,11 +152,12 @@ func Scan(r io.Reader, req Request) (Result, error) { Context: req.Context, }, Stats: Stats{ - LinesScanned: n, - BytesScanned: limited.n, - TotalHitsExact: truncated == "", - WindowStartByte: req.WindowStartByte, - FileSize: req.FileSize, + LinesScanned: n, + BytesScanned: limited.n, + TotalHitsExact: truncated == "", + WindowStartByte: req.WindowStartByte, + FileSize: req.FileSize, + ExpectedScanBytes: expectedScanBytes(req), }, Hits: []Hit{}, Redacted: req.Redact, @@ -445,6 +466,29 @@ func looksLikeLogLine(line string) bool { return false } +// progressSampleLines and progressSampleBytes bound how often the scan offers a +// progress sample, whichever trips first. +const ( + progressSampleLines = 4096 + progressSampleBytes = 512 << 10 +) + +// expectedScanBytes is how much this request could still read from its window. +// Zero means the source size is unknown (journal), not "nothing to scan". +func expectedScanBytes(req Request) int64 { + if req.FileSize <= 0 { + return 0 + } + available := req.FileSize - req.WindowStartByte + if available <= 0 { + return 0 + } + if req.MaxScanBytes > 0 && req.MaxScanBytes < available { + return req.MaxScanBytes + } + return available +} + type limitReader struct { r io.Reader n int64 @@ -510,3 +554,16 @@ func joinReason(existing, next string) string { } return existing + "," + next } + +// HasTruncationReason reports whether the comma-joined truncated_reason list +// contains want. One window can stop for several reasons at once +// ("max_scan_bytes,max_hits"), so callers must test membership rather than +// string equality. +func HasTruncationReason(reason, want string) bool { + for _, part := range strings.Split(reason, ",") { + if strings.TrimSpace(part) == want { + return true + } + } + return false +} diff --git a/internal/textsafe/scan_progress_test.go b/internal/textsafe/scan_progress_test.go new file mode 100644 index 0000000..48ded84 --- /dev/null +++ b/internal/textsafe/scan_progress_test.go @@ -0,0 +1,147 @@ +package textsafe + +import ( + "encoding/json" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// progressRecorder captures the samples a scan offers. +type progressRecorder struct { + samples []ScanProgress +} + +func (p *progressRecorder) Progress(s ScanProgress) { + p.samples = append(p.samples, s) +} + +// TestScanWithProgressSamplesAreBoundedAndMonotonic guards the monitoring +// contract: samples arrive during a long scan, in order, and never claim more +// bytes or lines than the scan has read. +func TestScanWithProgressSamplesAreBoundedAndMonotonic(t *testing.T) { + var body strings.Builder + for i := 0; i < 20000; i++ { + body.WriteString("2026-01-01 INFO line with pattern=matcher and padding\n") + } + req := Request{ + Kind: SourceFile, + Path: "/var/log/app.log", + Scan: ScanStart, + Pattern: "matcher", + FileSize: int64(body.Len()), + } + rec := &progressRecorder{} + out, err := ScanWithProgress(strings.NewReader(body.String()), req, rec) + require.NoError(t, err) + require.NotEmpty(t, rec.samples, "a 20k-line scan must offer progress samples") + + var lastBytes int64 + var lastLines int + for _, s := range rec.samples { + require.GreaterOrEqual(t, s.Bytes, lastBytes, "byte progress must not go backwards") + require.GreaterOrEqual(t, s.Lines, lastLines, "line progress must not go backwards") + require.LessOrEqual(t, s.Bytes, out.Stats.BytesScanned, "progress must not exceed the scan total") + require.Equal(t, int64(body.Len()), s.FileSize) + lastBytes, lastLines = s.Bytes, s.Lines + } + require.Positive(t, rec.samples[len(rec.samples)-1].MatchedLines, "pattern matches must be reported") + require.Greater(t, len(rec.samples), 1, "sampling must repeat during a long scan") +} + +// TestScanWithoutObserverMatchesScan pins the compatibility contract: adding a +// progress observer must not change what a scan returns. +func TestScanWithoutObserverMatchesScan(t *testing.T) { + req := Request{Kind: SourceFile, Path: "/var/log/app.log", Scan: ScanStart, Presets: []string{"exception"}} + plain, err := Scan(strings.NewReader(pythonTrace), req) + require.NoError(t, err) + rec := &progressRecorder{} + watched, err := ScanWithProgress(strings.NewReader(pythonTrace), req, rec) + require.NoError(t, err) + require.Equal(t, plain, watched) +} + +// TestExpectedScanBytesReportsWindowBudget documents the additive stats field: +// it is the byte window capped by --max-scan-bytes, and the empty value (not +// zero) when the source size is unknown. +func TestExpectedScanBytesReportsWindowBudget(t *testing.T) { + tests := []struct { + name string + req Request + want int64 + }{ + { + name: "whole file within budget", + req: Request{MaxScanBytes: 1 << 20, FileSize: 4096}, + want: 4096, + }, + { + name: "budget truncates the window", + req: Request{MaxScanBytes: 1 << 20, FileSize: 64 << 20}, + want: 1 << 20, + }, + { + name: "window already seeks into the file", + req: Request{MaxScanBytes: 8 << 20, FileSize: 3 << 20, WindowStartByte: 1 << 20}, + want: 2 << 20, + }, + { + name: "unknown source size", + req: Request{MaxScanBytes: 1 << 20, FileSize: 0}, + want: 0, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + req := tc.req + req.Kind = SourceFile + req.Path = "/var/log/app.log" + req.Scan = ScanStart + out, err := Scan(strings.NewReader("INFO ok\n"), req) + require.NoError(t, err) + require.Equal(t, tc.want, out.Stats.ExpectedScanBytes) + }) + } +} + +// TestExpectedScanBytesIsOmittedForJournal keeps sshx.text.v1 compatible: the +// field is additive, so unknown sources must not grow a misleading zero. +func TestExpectedScanBytesIsOmittedForJournal(t *testing.T) { + out := Result{ + Stats: Stats{LinesScanned: 3}, + Hits: []Hit{}, + } + encoded, err := json.Marshal(out) + require.NoError(t, err) + require.NotContains(t, string(encoded), "expected_scan_bytes") + + out.Stats.ExpectedScanBytes = 1 << 20 + encoded, err = json.Marshal(out) + require.NoError(t, err) + require.Contains(t, string(encoded), `"expected_scan_bytes":1048576`) +} + +func TestHasTruncationReason(t *testing.T) { + tests := []struct { + reason string + want string + wantOK bool + }{ + {reason: "max_scan_bytes", want: "max_scan_bytes", wantOK: true}, + {reason: "max_scan_bytes,max_hits", want: "max_scan_bytes", wantOK: true}, + {reason: "max_hits,max_scan_bytes", want: "max_scan_bytes", wantOK: true}, + {reason: "max_scan_bytes,max_hits", want: "max_hits", wantOK: true}, + {reason: "max_hits", want: "max_scan_bytes", wantOK: false}, + {reason: "max_bytes", want: "max_scan_bytes", wantOK: false}, + {reason: "", want: "max_scan_bytes", wantOK: false}, + } + + for _, tc := range tests { + t.Run(tc.reason+"/"+tc.want, func(t *testing.T) { + assert.Equal(t, tc.wantOK, HasTruncationReason(tc.reason, tc.want)) + }) + } +} diff --git a/internal/textsafe/types.go b/internal/textsafe/types.go index eae81ff..c16cc8e 100644 --- a/internal/textsafe/types.go +++ b/internal/textsafe/types.go @@ -83,6 +83,28 @@ type Stats struct { TotalHitsExact bool `json:"total_hits_exact"` WindowStartByte int64 `json:"window_start_byte,omitempty"` FileSize int64 `json:"file_size,omitempty"` + // ExpectedScanBytes is how much this request expects to read: the byte + // window it opened, capped by --max-scan-bytes. A caller can weigh it + // before trusting TotalHitsExact, and a mismatch with BytesScanned means + // the scan stopped early instead of covering its window. It is additive to + // sshx.text.v1 and omitted when the source size is unknown (journal). + ExpectedScanBytes int64 `json:"expected_scan_bytes,omitempty"` +} + +// ScanProgress is a bounded progress sample taken while a scan is running. +// MatchedLines counts lines that matched --pattern so far and stays zero when +// no pattern was requested. +type ScanProgress struct { + Bytes int64 + Lines int + MatchedLines int + FileSize int64 +} + +// ProgressObserver receives progress samples. Implementations must not block +// and must never write to stdout, which carries the JSON result. +type ProgressObserver interface { + Progress(ScanProgress) } // Result is the engine output before host/lifecycle wrapping. From 719eecd6ba7d6c5588a16becec56d5bd96ed9e15 Mon Sep 17 00:00:00 2001 From: Mira Voss Date: Tue, 22 Sep 2026 22:56:21 +0800 Subject: [PATCH 3/7] feat(app): report blocked and sudo boundaries on stderr A policy block carries its reason in the --json document, so a caller that prints only exit_code/stdout/stderr read "exit_code=-1" with two empty streams and concluded the refusal was silent. Mirror the decision and the flattened reason to stderr in --json mode. stdout is unchanged: the same one-document payload, with the same block fields. The mirror is emitted once, and only for a real admission block. Sudo auto-fill still rewrites a leading sudo only. That boundary was correct but invisible: `cd /data/app && sudo docker compose up -d` died with "sudo: a password is required" 29 times in one session with no explanation. Warn before connecting when a command runs sudo in command position after a segment or wrapper, and explain the refusal afterwards when the remote output shows a sudo password prompt. Both hints write straight to stderr, because a caller reading a failed run may have quieted diagnostics; the run path names the failing target. The auto-fill scope itself is unchanged. commandTokenIndex is extracted from commandInPosition so sudo position detection shares the shell segmentation rules, and sudo gets its own walker because commandWrappers already skips it. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- internal/app/app.go | 19 +++ internal/app/lifecycle.go | 61 ++++++- internal/app/lifecycle_policy_test.go | 178 +++++++++++++++++++++ internal/app/run.go | 29 ++++ internal/sshclient/validate.go | 96 +++++++++++ internal/sshclient/validate_destructive.go | 53 +++--- internal/sshclient/validate_sudo_test.go | 84 ++++++++++ 7 files changed, 493 insertions(+), 27 deletions(-) create mode 100644 internal/app/lifecycle_policy_test.go create mode 100644 internal/sshclient/validate_sudo_test.go diff --git a/internal/app/app.go b/internal/app/app.go index 999cdf1..744ac3d 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "io" "net" "os" "os/signal" @@ -339,6 +340,10 @@ func RunContext(ctx context.Context, args []string) (err error) { config.SudoPassword = password logger.GetLogger().Success("Sudo password will be auto-filled when prompted") } + } else if hint, needed := sshclient.NonLeadingSudoHint(config.Command); needed && config.SudoKey != "" { + // Warn before connecting: this command will prompt for a password that + // no non-interactive session can answer. + logger.GetLogger().Warning("sudo password auto-fill skipped for this command: %s", hint) } // Create SSH client @@ -377,6 +382,7 @@ func runCommand(client *sshclient.SSHClient, config *sshclient.Config, audit *au res, execErr := client.RunCommand(config.JSONOutput) dur := time.Since(start) audit.recordCommandResult(config, client.AuthMethodUsed(), res, dur, classifyError(execErr), execErr) + reportSudoPromptFailure(os.Stderr, config.Command, res.Stderr+res.Stdout) if config.JSONOutput { if outputErr := emitCommandJSON(config, client.AuthMethodUsed(), res, dur, classifyError(execErr), execErr); outputErr != nil { @@ -428,6 +434,19 @@ func reportSSHFailure(config *sshclient.Config, audit *auditRecorder, authMethod return err } +// reportSudoPromptFailure explains a sudo refusal sshx cannot help with: the +// stored password is only injected for a leading sudo, so a mid-command sudo +// stops with "a password is required". It writes straight to stderr rather than +// through the logger, because it explains a failed run to a caller that may be +// running with diagnostics quieted. +func reportSudoPromptFailure(w io.Writer, command, output string) { + hint, needed := sshclient.NonLeadingSudoHint(command) + if !needed || !sshclient.SudoPasswordPromptFailure(output) { + return + } + fmt.Fprintf(w, "sshx: %s\n", hint) +} + // emitCommandJSON writes a single JSON result line to stdout. Diagnostic logs go // to stderr, so stdout stays a pure machine-readable stream. func emitCommandJSON(config *sshclient.Config, authMethod sshclient.AuthMethod, res sshclient.ExecResult, dur time.Duration, errKind string, execErr error) error { diff --git a/internal/app/lifecycle.go b/internal/app/lifecycle.go index fc841bb..93147bd 100644 --- a/internal/app/lifecycle.go +++ b/internal/app/lifecycle.go @@ -4,6 +4,9 @@ import ( "bytes" "encoding/json" "fmt" + "io" + "os" + "strings" "time" "github.com/talkincode/sshx/internal/execution" @@ -111,12 +114,64 @@ func emitLifecycleJSON(config *sshclient.Config, value any) error { if err != nil { return err } + // Write the human-readable mirror first so the JSON document stays the last + // line a caller that merges stderr into stdout would have to parse. + reportPolicyRejection(os.Stderr, document) if err := encodeJSON(document); err != nil { return fmt.Errorf("%w: deliver execution result: %w", execution.ErrLocalIO, err) } return nil } +// reportPolicyRejection mirrors a blocked admission decision to stderr. The +// rejection predicate is machine-readable (exit_code=-1, error_kind=blocked, +// phase=admission, executed=false) but lives inside the stdout document, which +// callers that surface only stdout/stderr used to read as a silent refusal. +// stdout keeps exactly one JSON document, so --json stays machine-parsable. +func reportPolicyRejection(w io.Writer, document map[string]json.RawMessage) { + if documentString(document, "error_kind") != execution.ErrorKindBlocked { + return + } + phase := documentString(document, "phase") + if phase == "" { + phase = execution.PhaseAdmission + } + executed := strings.TrimSpace(string(document["executed"])) + if executed != "true" { + executed = "false" + } + exitCode := -1 + if raw, ok := document["exit_code"]; ok { + _ = json.Unmarshal(raw, &exitCode) //nolint:errcheck // only reads the optional numeric projection + } + fmt.Fprintf(w, "sshx: blocked by safety policy (phase=%s, error_kind=%s, executed=%s, exit_code=%d); no remote command ran\n", + phase, execution.ErrorKindBlocked, executed, exitCode) + if reason := flattenPolicyReason(documentString(document, "error")); reason != "" { + fmt.Fprintf(w, "sshx: block reason: %s\n", reason) + } +} + +// flattenPolicyReason collapses a multi-line policy message into one greppable +// line. +func flattenPolicyReason(message string) string { + parts := strings.Split(message, "\n") + kept := make([]string, 0, len(parts)) + for _, part := range parts { + if trimmed := strings.TrimSpace(part); trimmed != "" { + kept = append(kept, trimmed) + } + } + return strings.Join(kept, " | ") +} + +func documentString(document map[string]json.RawMessage, key string) string { + var text string + if raw, ok := document[key]; ok { + _ = json.Unmarshal(raw, &text) //nolint:errcheck // only reads optional string projections + } + return text +} + func finalizeLifecycle(config *sshclient.Config, value any) (map[string]json.RawMessage, error) { data, err := marshalLifecycleValue(value) if err != nil { @@ -158,11 +213,7 @@ func finalizeLifecycle(config *sshclient.Config, value any) (map[string]json.Raw } } stringField := func(key string) string { - var text string - if raw, ok := document[key]; ok { - _ = json.Unmarshal(raw, &text) //nolint:errcheck // only reads optional string projections - } - return text + return documentString(document, key) } code := -1 if raw, ok := document["exit_code"]; ok { diff --git a/internal/app/lifecycle_policy_test.go b/internal/app/lifecycle_policy_test.go new file mode 100644 index 0000000..e2d855b --- /dev/null +++ b/internal/app/lifecycle_policy_test.go @@ -0,0 +1,178 @@ +package app + +import ( + "bytes" + "encoding/json" + "errors" + "io" + "os" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/talkincode/sshx/internal/sshclient" +) + +// captureStreams splits os.Stdout and os.Stderr into separate pipes so a test +// can assert on each stream independently. +func captureStreams(t *testing.T, fn func()) (stdout, stderr []byte) { + t.Helper() + + oldStdout, oldStderr := os.Stdout, os.Stderr + outR, outW, err := os.Pipe() + require.NoError(t, err) + errR, errW, err := os.Pipe() + require.NoError(t, err) + + type result struct { + data []byte + err error + } + read := func(r *os.File) chan result { + ch := make(chan result, 1) + go func() { + var buf bytes.Buffer + _, copyErr := io.Copy(&buf, r) + ch <- result{data: buf.Bytes(), err: copyErr} + }() + return ch + } + outCh, errCh := read(outR), read(errR) + + os.Stdout, os.Stderr = outW, errW + func() { + defer func() { + os.Stdout, os.Stderr = oldStdout, oldStderr + _ = outW.Close() //nolint:errcheck // test cleanup + _ = errW.Close() //nolint:errcheck // test cleanup + }() + fn() + }() + + outRes := <-outCh + errRes := <-errCh + require.NoError(t, outRes.err) + require.NoError(t, errRes.err) + require.NoError(t, outR.Close()) + require.NoError(t, errR.Close()) + return outRes.data, errRes.data +} + +// TestReportPolicyRejectionMirrorsBlockedDecision is the regression guard for +// the silent-refusal report: a blocked admission decision must reach stderr, +// where callers that only print the streams can see it. +func TestReportPolicyRejectionMirrorsBlockedDecision(t *testing.T) { + document := map[string]json.RawMessage{ + "error_kind": json.RawMessage(`"blocked"`), + "phase": json.RawMessage(`"admission"`), + "executed": json.RawMessage(`false`), + "exit_code": json.RawMessage(`-1`), + "error": json.RawMessage(`"⚠️ Dangerous command blocked\nCommand: docker exec c psql -c 'select 1'\nReason: bypasses the guarded SQL pipeline. Use: sshx sql -h= --db= [--docker=] \"\""`), + } + + var out bytes.Buffer + reportPolicyRejection(&out, document) + lines := strings.Split(strings.TrimRight(out.String(), "\n"), "\n") + require.Len(t, lines, 2, "expected a decision line and a reason line") + assert.Contains(t, lines[0], "blocked by safety policy") + assert.Contains(t, lines[0], "phase=admission") + assert.Contains(t, lines[0], "error_kind=blocked") + assert.Contains(t, lines[0], "executed=false") + assert.Contains(t, lines[0], "exit_code=-1") + assert.Contains(t, lines[1], "bypasses the guarded SQL pipeline") + assert.Contains(t, lines[1], "|", "multi-line reasons must be flattened to one line") + assert.Contains(t, lines[1], "sshx sql", "the reason must keep the guarded alternative") +} + +// TestReportPolicyRejectionIgnoresOtherFailures keeps the mirror narrow: only a +// policy block earns it, so ordinary remote failures are not annotated. +func TestReportPolicyRejectionIgnoresOtherFailures(t *testing.T) { + for _, document := range []map[string]json.RawMessage{ + {"error_kind": json.RawMessage(`"remote_error"`), "error": json.RawMessage(`"boom"`)}, + {"error_kind": json.RawMessage(`""`)}, + {}, + } { + var out bytes.Buffer + reportPolicyRejection(&out, document) + assert.Empty(t, out.String()) + } +} + +// TestReportPolicyRejectionDefaultsMissingFields: a blocked decision without +// the optional projections still reads as "nothing ran". +func TestReportPolicyRejectionDefaultsMissingFields(t *testing.T) { + var out bytes.Buffer + reportPolicyRejection(&out, map[string]json.RawMessage{ + "error_kind": json.RawMessage(`"blocked"`), + }) + line := out.String() + assert.Contains(t, line, "phase=admission") + assert.Contains(t, line, "executed=false") + assert.Contains(t, line, "exit_code=-1") + assert.Contains(t, line, "no remote command ran") +} + +// TestBlockedJSONKeepsStdoutPureAndMirrorsStderr runs the real blocked +// admission path: stdout must stay exactly one JSON document while stderr +// carries the human-readable rejection. +func TestBlockedJSONKeepsStdoutPureAndMirrorsStderr(t *testing.T) { + config := &sshclient.Config{ + Mode: "ssh", + Host: "db1.example.net", + Port: "22", + User: "operator", + Command: `docker exec teamsacs_pgdb18 psql -U teamsacs -d teamsacs -At -c 'select 1'`, + JSONOutput: true, + } + blocked := &sshclient.CommandBlockedError{ + Command: config.Command, + Reason: `Direct PostgreSQL client execution ("psql") bypasses the guarded SQL pipeline. Use: sshx sql -h= --db= [--docker=] "" (adds classification, backups, and audit)`, + } + + var runErr error + stdout, stderr := captureStreams(t, func() { + runErr = reportSSHFailure(config, nil, sshclient.AuthMethodUnknown, "blocked", blocked) + }) + require.ErrorIs(t, runErr, ErrReported) + + // stdout: exactly one JSON document, nothing else. + assert.True(t, json.Valid(bytes.TrimSpace(stdout)), "stdout must be a single JSON document: %q", stdout) + assert.Equal(t, 1, strings.Count(strings.TrimSpace(string(stdout)), "\n")+1, "stdout must hold one JSON line") + + var document map[string]any + require.NoError(t, json.Unmarshal(stdout, &document)) + assert.Equal(t, "blocked", document["error_kind"]) + assert.Equal(t, "admission", document["phase"]) + assert.Equal(t, false, document["executed"]) + assert.EqualValues(t, -1, document["exit_code"]) + + // stderr: the rejection a caller can print. + require.NotEmpty(t, stderr, "a blocked --json run must explain itself on stderr") + assert.Contains(t, string(stderr), "blocked by safety policy") + assert.Contains(t, string(stderr), "phase=admission") + assert.Contains(t, string(stderr), "sshx sql") + assert.NotContains(t, string(stdout), "blocked by safety policy", "the mirror must not leak into stdout") +} + +// TestNonBlockedJSONFailureHasNoMirror: a plain remote failure keeps today's +// behavior and writes nothing extra to stderr. +func TestNonBlockedJSONFailureHasNoMirror(t *testing.T) { + config := &sshclient.Config{ + Mode: "ssh", + Host: "db1.example.net", + Port: "22", + User: "operator", + Command: "systemctl restart api", + JSONOutput: true, + } + + var runErr error + stdout, stderr := captureStreams(t, func() { + runErr = reportSSHFailure(config, nil, sshclient.AuthMethodUnknown, "connect", errors.New("dial tcp: connection refused")) + }) + require.ErrorIs(t, runErr, ErrReported) + assert.NotContains(t, string(stderr), "blocked by safety policy") + assert.True(t, json.Valid(bytes.TrimSpace(stdout))) +} diff --git a/internal/app/run.go b/internal/app/run.go index d31f76e..1683e5f 100644 --- a/internal/app/run.go +++ b/internal/app/run.go @@ -121,12 +121,14 @@ func HandleRun(config *sshclient.Config, audit *auditRecorder) error { if execErr != nil { if outcome.RunID != "" { recordRunAudit(audit, config, req, snap, outcome) + reportRunSudoPromptFailures(outcome, req.Action.Command) return execErr } return reportRunRequestFailure(config, audit, execErr) } recordRunAudit(audit, config, req, snap, outcome) + reportRunSudoPromptFailures(outcome, req.Action.Command) // Single-target --json emits one versioned result document. if req.JSONOutput && !req.JSONLOutput && outcome.Single != nil { @@ -146,6 +148,28 @@ func HandleRun(config *sshclient.Config, audit *auditRecorder) error { } } +// reportRunSudoPromptFailures explains a per-target sudo refusal that sshx +// cannot auto-fill: the stored password only rewrites a leading sudo, so a +// mid-command sudo stops with "a password is required". It writes straight to +// stderr because the caller explaining a failure may be running with +// diagnostics quieted, and stdout must keep exactly one result document. +func reportRunSudoPromptFailures(outcome execution.RunOutcome, command string) { + hint, needed := sshclient.NonLeadingSudoHint(command) + if !needed { + return + } + for _, res := range outcome.Results { + if !sshclient.SudoPasswordPromptFailure(res.Stderr + res.Stdout) { + continue + } + if label := res.Target.Alias; label != "" { + fmt.Fprintf(os.Stderr, "sshx: [%s] %s\n", label, hint) + continue + } + fmt.Fprintf(os.Stderr, "sshx: %s\n", hint) + } +} + type executionNoopEvents struct{} func (executionNoopEvents) WriteEvent(execution.Event) error { return nil } @@ -389,6 +413,11 @@ func buildRunRequest(config *sshclient.Config) (*execution.Request, *execution.P req.Action.Intent = execution.IntentRead } } + if hint, needed := sshclient.NonLeadingSudoHint(req.Action.Command); needed { + // Non-interactive sessions cannot answer a mid-command sudo prompt and + // auto-fill only rewrites the leading token. Say so before connecting. + logger.GetLogger().Warning("%s", hint) + } if req.Policy.FailureMode == "" { req.Policy.FailureMode = execution.FailureContinue } diff --git a/internal/sshclient/validate.go b/internal/sshclient/validate.go index cdfc251..0943e30 100644 --- a/internal/sshclient/validate.go +++ b/internal/sshclient/validate.go @@ -116,6 +116,102 @@ func isCommandWhitespace(ch byte) bool { return ch == ' ' || ch == '\t' || ch == '\r' || ch == '\n' } +// NonLeadingSudoHint reports a `sudo` invocation in command position that sshx +// cannot feed a password to, because auto-fill only rewrites a leading `sudo` +// token (see sudoStdinCommand). `cd /data/app && sudo docker compose up -d` +// therefore runs verbatim and sudo prompts for a password it can never read +// over a non-interactive session. +// +// The returned hint tells the operator how to restructure the command. The +// auto-fill scope itself is unchanged: sshx still fills only the leading form. +func NonLeadingSudoHint(command string) (string, bool) { + trimmed := strings.TrimSpace(command) + if trimmed == "" { + return "", false + } + if _, ok := leadingSudoRemainder(trimmed); ok { + return "", false + } + if !sudoInCommandPosition(trimmed, 0) { + return "", false + } + return "sudo is not the first token, so sshx cannot auto-fill a stored sudo password " + + "(auto-fill only rewrites a leading `sudo`). Run the privileged part as " + + "`sudo sh -c \"\"`, or move `sudo` to the front.", true +} + +// sudoInCommandPosition reports whether any shell segment executes sudo as its +// command, recursing into `sh -c '