types/logger, logtail: add mechanism to do structured JSON logs

e.g. the change to ipnlocal in this commit ultimately logs out:

{"logtail":{"client_time":"2022-02-17T20:40:30.511381153-08:00","server_time":"2022-02-18T04:40:31.057771504Z"},"type":"Hostinfo","val":{"GoArch":"amd64","Hostname":"tsdev","IPNVersion":"1.21.0-date.20220107","OS":"linux","OSVersion":"Debian 11.2 (bullseye); kernel=5.10.0-10-amd64"},"v":1}

Change-Id: I668646b19aeae4a2fed05170d7b279456829c844
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

ipn/ipnlocal/local.go

@@ -172,7 +172,7 @@ func NewLocalBackend(logf logger.Logf, logid string, store ipn.StateStore, diale
 	}
 
 	hi := hostinfo.New()
-	logf("Host: %s/%s, %s", hi.OS, hi.GoArch, hi.OSVersion)
+	logf.JSON(1, "Hostinfo", hi)
 	envknob.LogCurrent(logf)
 	if dialer == nil {
 		dialer = new(tsdial.Dialer)

logtail/logtail.go

@@ -530,6 +530,9 @@ func (l *Logger) encode(buf []byte, level int) []byte {
 			"client_time": now.Format(time.RFC3339Nano),
 		}
 	}
+	if level > 0 {
+		obj["v"] = level
+	}
 
 	b, err := json.Marshal(obj)
 	if err != nil {
@@ -577,6 +580,7 @@ var (
 	openBracketV = []byte("[v")
 	v1           = []byte("[v1] ")
 	v2           = []byte("[v2] ")
+	vJSON        = []byte("[v\x00JSON]") // precedes log level '0'-'9' byte, then JSON value
 )
 
 // level 0 is normal (or unknown) level; 1+ are increasingly verbose
@@ -590,5 +594,14 @@ func parseAndRemoveLogLevel(buf []byte) (level int, cleanBuf []byte) {
 	if bytes.Contains(buf, v2) {
 		return 2, bytes.ReplaceAll(buf, v2, nil)
 	}
+	if i := bytes.Index(buf, vJSON); i != -1 {
+		rest := buf[i+len(vJSON):]
+		if len(rest) >= 2 {
+			v := rest[0]
+			if v >= '0' && v <= '9' {
+				return int(v - '0'), rest[1:]
+			}
+		}
+	}
 	return 0, buf
 }

logtail/logtail_test.go

@@ -275,6 +275,11 @@ func TestParseAndRemoveLogLevel(t *testing.T) {
 			0,
 			"[v3] no level 3",
 		},
+		{
+			"some ignored text then [v\x00JSON]5{\"foo\":1234}",
+			5,
+			`{"foo":1234}`,
+		},
 	}
 
 	for _, tt := range tests {
@@ -368,6 +373,14 @@ func TestEncode(t *testing.T) {
 			`{"foo":"bar"}`,
 			`{"foo":"bar","logtail":{"client_time":"1970-01-01T00:02:03.000000456Z"}}` + "\n",
 		},
+		{
+			"foo: [v\x00JSON]0{\"foo\":1}",
+			"{\"foo\":1,\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\"}}\n",
+		},
+		{
+			"foo: [v\x00JSON]2{\"foo\":1}",
+			"{\"foo\":1,\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\"},\"v\":2}\n",
+		},
 	}
 	for _, tt := range tests {
 		buf := new(simpleMemBuf)

types/logger/logger.go

@@ -9,7 +9,9 @@ package logger
 
 import (
 	"bufio"
+	"bytes"
 	"container/list"
+	"encoding/json"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -35,6 +37,49 @@ type Context context.Context
 
 type logfKey struct{}
 
+// jenc is a json.Encode + bytes.Buffer pair wired up to be reused in a pool.
+type jenc struct {
+	buf bytes.Buffer
+	enc *json.Encoder
+}
+
+var jencPool = &sync.Pool{New: func() interface{} {
+	je := new(jenc)
+	je.enc = json.NewEncoder(&je.buf)
+	return je
+}}
+
+// JSON marshals v as JSON and writes it to logf formatted with the annotation to make logtail
+// treat it as a structured log.
+//
+// The recType is the record type and becomes the key of the wrapper
+// JSON object that is logged. That is, if recType is "foo" and v is
+// 123, the value logged is {"foo":123}.
+//
+// Do not use recType "logtail" or "v", with any case. Those are
+// reserved for the logging system.
+//
+// The level can be from 0 to 9. Levels from 1 to 9 are included in
+// the logged JSON object, like {"foo":123,"v":2}.
+func (logf Logf) JSON(level int, recType string, v interface{}) {
+	je := jencPool.Get().(*jenc)
+	defer jencPool.Put(je)
+	je.buf.Reset()
+	je.buf.WriteByte('{')
+	je.enc.Encode(recType)
+	je.buf.Truncate(je.buf.Len() - 1) // remove newline from prior Encode
+	je.buf.WriteByte(':')
+	if err := je.enc.Encode(v); err != nil {
+		logf("[unexpected]: failed to encode structured JSON log record of type %q / %T: %v", recType, v, err)
+		return
+	}
+	je.buf.Truncate(je.buf.Len() - 1) // remove newline from prior Encode
+	je.buf.WriteByte('}')
+	// Magic prefix recognized by logtail:
+	logf("[v\x00JSON]%d%s", level%10, je.buf.Bytes())
+
+}
+
 // FromContext extracts a log function from ctx.
 func FromContext(ctx Context) Logf {
 	v := ctx.Value(logfKey{})

types/logger/logger_test.go

@@ -15,6 +15,7 @@ import (
 	"time"
 
 	qt "github.com/frankban/quicktest"
+	"tailscale.com/tailcfg"
 )
 
 func TestFuncWriter(t *testing.T) {
@@ -211,3 +212,13 @@ func TestContext(t *testing.T) {
 	logf("a")
 	c.Assert(called, qt.IsTrue)
 }
+
+func TestJSON(t *testing.T) {
+	var buf bytes.Buffer
+	var logf Logf = func(f string, a ...interface{}) { fmt.Fprintf(&buf, f, a...) }
+	logf.JSON(1, "foo", &tailcfg.Hostinfo{})
+	want := "[v\x00JSON]1" + `{"foo":{"OS":"","Hostname":""}}`
+	if got := buf.String(); got != want {
+		t.Errorf("mismatch\n got: %q\nwant: %q\n", got, want)
+	}
+}