git » chasquid » commit 5e827fe

diff --git a/internal/trace/trace.go b/internal/trace/trace.go
index 4677640..6fe2fb3 100644
--- a/internal/trace/trace.go
+++ b/internal/trace/trace.go
@@ -4,6 +4,7 @@ package trace
 import (
 	"fmt"
 	"strconv"
+	"unicode/utf8"
 
 	"blitiri.com.ar/go/chasquid/internal/nettrace"
 	"blitiri.com.ar/go/log"
@@ -49,7 +50,7 @@ func (t *Trace) Debugf(format string, a ...any) {
 
 func (t *Trace) printf(level log.Level, format string, a ...any) {
 	// Format the message only once, as it can be expensive.
-	msg := fmt.Sprintf(format, a...)
+	msg := truncate(fmt.Sprintf(format, a...))
 	t.t.Printf("%s", msg)
 
 	// Only quote and log the message if it's going to be logged.
@@ -62,22 +63,24 @@ func (t *Trace) printf(level log.Level, format string, a ...any) {
 func (t *Trace) Errorf(format string, a ...any) error {
 	// Note we can't just call t.Error here, as it breaks caller logging.
 	err := fmt.Errorf(format, a...)
+	msg := truncate(err.Error())
 	t.t.SetError()
-	t.t.Printf("error: %v", err)
+	t.t.Printf("error: %s", msg)
 
 	log.Log(log.Info, 1, "%s %s: error: %s", t.family, t.title,
-		quote(err.Error()))
+		quote(msg))
 	return err
 }
 
 // Error marks the trace as having seen an error, and also logs it to the
 // trace's log.
 func (t *Trace) Error(err error) error {
+	msg := truncate(err.Error())
 	t.t.SetError()
-	t.t.Printf("error: %v", err)
+	t.t.Printf("error: %s", msg)
 
 	log.Log(log.Info, 1, "%s %s: error: %s", t.family, t.title,
-		quote(err.Error()))
+		quote(msg))
 
 	return err
 }
@@ -87,6 +90,25 @@ func (t *Trace) Finish() {
 	t.t.Finish()
 }
 
+// Maximum length of a message in the trace or the log, in characters (so up
+// to 4x that in bytes); longer ones get truncated. Messages can contain
+// attacker-controlled data (e.g. headers, DNS records, remote server
+// responses), and traces are kept in memory after they finish, so we need a
+// cap. It is set well above the normal message sizes, so in practice it only
+// affects pathological cases.
+const maxMsgLen = 8 * 1024
+
+// truncate s to maxMsgLen characters, noting its original length.
+func truncate(s string) string {
+	// Check the length in bytes first, as it's much cheaper, and it can't
+	// have more characters than bytes.
+	if len(s) <= maxMsgLen || utf8.RuneCountInString(s) <= maxMsgLen {
+		return s
+	}
+	return fmt.Sprintf("%.*s… [truncated, %d bytes total]",
+		maxMsgLen, s, len(s))
+}
+
 func quote(s string) string {
 	qs := strconv.Quote(s)
 	return qs[1 : len(qs)-1]
diff --git a/internal/trace/trace_test.go b/internal/trace/trace_test.go
index 48e2d93..cabb9bd 100644
--- a/internal/trace/trace_test.go
+++ b/internal/trace/trace_test.go
@@ -101,6 +101,76 @@ func TestLog(t *testing.T) {
 	}
 }
 
+func TestTruncate(t *testing.T) {
+	rep := strings.Repeat
+	cases := []struct {
+		in, want string
+	}{
+		{"", ""},
+		{"short", "short"},
+		{rep("a", maxMsgLen), rep("a", maxMsgLen)},
+		{rep("a", maxMsgLen+1),
+			rep("a", maxMsgLen) + "… [truncated, 8193 bytes total]"},
+
+		// The limit is in characters, not bytes ("ñ" is 2 bytes).
+		{rep("ñ", maxMsgLen), rep("ñ", maxMsgLen)},
+		{rep("ñ", maxMsgLen+1),
+			rep("ñ", maxMsgLen) + "… [truncated, 16386 bytes total]"},
+
+		// Invalid UTF-8 bytes count as one character each, and are kept.
+		{rep("\xff", maxMsgLen+1),
+			rep("\xff", maxMsgLen) + "… [truncated, 8193 bytes total]"},
+	}
+	for i, c := range cases {
+		if got := truncate(c.in); got != c.want {
+			t.Errorf("%d: truncate(%d bytes) = %q (%d bytes), want %q",
+				i, len(c.in), got[max(0, len(got)-40):], len(got),
+				c.want[max(0, len(c.want)-40):])
+		}
+	}
+}
+
+func TestTruncateMessages(t *testing.T) {
+	buf := setupLog(t, log.Debug)
+	tr := New("TestTruncateMessages", "title")
+
+	long := strings.Repeat("x", 3*maxMsgLen)
+	tr.Printf("printf %s", long)
+	tr.Debugf("debugf %s", long)
+	err := tr.Errorf("errorf %s", long)
+	tr.Error(errors.New("error " + long))
+
+	// The error returned by Errorf must not be truncated.
+	if len(err.Error()) != len("errorf ")+len(long) {
+		t.Errorf("Errorf returned a truncated error (%d bytes)",
+			len(err.Error()))
+	}
+
+	// All messages are truncated in the log...
+	lines := strings.Split(strings.TrimSpace(buf.String()), "\n")
+	if len(lines) != 4 {
+		t.Fatalf("expected 4 log lines, got %d", len(lines))
+	}
+	for _, l := range lines {
+		if len(l) > maxMsgLen+100 ||
+			!strings.HasSuffix(l, " bytes total]") {
+			t.Errorf("log line not truncated (%d bytes): ...%s",
+				len(l), l[max(0, len(l)-60):])
+		}
+	}
+
+	// ... and in the trace.
+	body := traceEvents(t, "TestTruncateMessages")
+	if n := strings.Count(body, " bytes total]"); n != 4 {
+		t.Errorf("expected 4 truncated events in the trace, got %d", n)
+	}
+	if len(body) > 4*maxMsgLen+10*1024 {
+		t.Errorf("trace too large (%d bytes), events not truncated?",
+			len(body))
+	}
+	tr.Finish()
+}
+
 func TestTraceEvents(t *testing.T) {
 	// Debug messages are added to the trace even if they are not logged.
 	setupLog(t, log.Info)