From 5d9ab502f397238ec6fda43de388403cc39e93ec Mon Sep 17 00:00:00 2001
From: Brad Fitzpatrick <bradfitz@tailscale.com>
Date: Sun, 13 Feb 2022 08:54:23 -0800
Subject: [PATCH] logtail: don't strip verbose level on upload

For analysis of log spam.

Bandwidth is ~unchanged from had we not stripped the "[vN] " from
text; it just gets restructed intot he new "v":N, field.  I guess it
adds one byte.

Updates #1548

Change-Id: Ie00a4e0d511066a33d10dc38d765d92b0b044697
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
---
 logtail/logtail.go      | 18 ++++++++++----
 logtail/logtail_test.go | 54 +++++++++++++++++++++++++++++++++++++++--
 2 files changed, 65 insertions(+), 7 deletions(-)

diff --git a/logtail/logtail.go b/logtail/logtail.go
index bd30882a5..c0123e362 100644
--- a/logtail/logtail.go
+++ b/logtail/logtail.go
@@ -255,7 +255,7 @@ func (l *Logger) drainPending(scratch []byte) (res []byte) {
 				l.explainedRaw = true
 			}
 			fmt.Fprintf(l.stderr, "RAW-STDERR: %s", b)
-			b = l.encodeText(b, true)
+			b = l.encodeText(b, true, 0)
 		}
 
 		if entries > 0 {
@@ -418,7 +418,7 @@ func (l *Logger) send(jsonBlob []byte) (int, error) {
 
 // TODO: instead of allocating, this should probably just append
 // directly into the output log buffer.
-func (l *Logger) encodeText(buf []byte, skipClientTime bool) []byte {
+func (l *Logger) encodeText(buf []byte, skipClientTime bool, level int) []byte {
 	now := l.timeNow()
 
 	// Factor in JSON encoding overhead to try to only do one alloc
@@ -463,6 +463,14 @@ func (l *Logger) encodeText(buf []byte, skipClientTime bool) []byte {
 		}
 	}
 
+	// Add the log level, if non-zero. Note that we only use log
+	// levels 1 and 2 currently. It's unlikely we'll ever make it
+	// past 9.
+	if level > 0 && level < 10 {
+		b = append(b, `"v":`...)
+		b = append(b, '0'+byte(level))
+		b = append(b, ',')
+	}
 	b = append(b, "\"text\": \""...)
 	for _, c := range buf {
 		switch c {
@@ -493,9 +501,9 @@ func (l *Logger) encodeText(buf []byte, skipClientTime bool) []byte {
 	return b
 }
 
-func (l *Logger) encode(buf []byte) []byte {
+func (l *Logger) encode(buf []byte, level int) []byte {
 	if buf[0] != '{' {
-		return l.encodeText(buf, l.skipClientTime) // text fast-path
+		return l.encodeText(buf, l.skipClientTime, level) // text fast-path
 	}
 
 	now := l.timeNow()
@@ -560,7 +568,7 @@ func (l *Logger) Write(buf []byte) (int, error) {
 			l.stderr.Write(withNL)
 		}
 	}
-	b := l.encode(buf)
+	b := l.encode(buf, level)
 	_, err := l.send(b)
 	return len(buf), err
 }
diff --git a/logtail/logtail_test.go b/logtail/logtail_test.go
index cee0d1658..2ab5ab572 100644
--- a/logtail/logtail_test.go
+++ b/logtail/logtail_test.go
@@ -217,7 +217,7 @@ func TestLoggerEncodeTextAllocs(t *testing.T) {
 	lg := &Logger{timeNow: time.Now}
 	inBuf := []byte("some text to encode")
 	err := tstest.MinAllocsPerRun(t, 1, func() {
-		sink = lg.encodeText(inBuf, false)
+		sink = lg.encodeText(inBuf, false, 0)
 	})
 	if err != nil {
 		t.Fatal(err)
@@ -328,10 +328,60 @@ func unmarshalOne(t *testing.T, body []byte) map[string]interface{} {
 func TestEncodeTextTruncation(t *testing.T) {
 	lg := &Logger{timeNow: time.Now, lowMem: true}
 	in := bytes.Repeat([]byte("a"), 300)
-	b := lg.encodeText(in, true)
+	b := lg.encodeText(in, true, 0)
 	got := string(b)
 	want := `{"text": "` + strings.Repeat("a", 255) + `…+45"}` + "\n"
 	if got != want {
 		t.Errorf("got:\n%qwant:\n%q\n", got, want)
 	}
 }
+
+type simpleMemBuf struct {
+	Buffer
+	buf bytes.Buffer
+}
+
+func (b *simpleMemBuf) Write(p []byte) (n int, err error) { return b.buf.Write(p) }
+
+func TestEncode(t *testing.T) {
+	tests := []struct {
+		in   string
+		want string
+	}{
+		{
+			"normal",
+			`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z"}, "text": "normal"}` + "\n",
+		},
+		{
+			"and a [v1] level one",
+			`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z"}, "v":1,"text": "and a level one"}` + "\n",
+		},
+		{
+			"[v2] some verbose two",
+			`{"logtail": {"client_time": "1970-01-01T00:02:03.000000456Z"}, "v":2,"text": "some verbose two"}` + "\n",
+		},
+		{
+			"{}",
+			`{"logtail":{"client_time":"1970-01-01T00:02:03.000000456Z"}}` + "\n",
+		},
+		{
+			`{"foo":"bar"}`,
+			`{"foo":"bar","logtail":{"client_time":"1970-01-01T00:02:03.000000456Z"}}` + "\n",
+		},
+	}
+	for _, tt := range tests {
+		buf := new(simpleMemBuf)
+		lg := &Logger{
+			timeNow: func() time.Time { return time.Unix(123, 456).UTC() },
+			buffer:  buf,
+		}
+		io.WriteString(lg, tt.in)
+		got := buf.buf.String()
+		if got != tt.want {
+			t.Errorf("for %q,\n got: %#q\nwant: %#q\n", tt.in, got, tt.want)
+		}
+		if err := json.Compact(new(bytes.Buffer), buf.buf.Bytes()); err != nil {
+			t.Errorf("invalid output JSON for %q: %s", tt.in, got)
+		}
+	}
+}