From 84138450a4c2bc9c826bdffa75976f229ed3ae59 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Thu, 17 Feb 2022 20:41:49 -0800 Subject: [PATCH] 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 --- ipn/ipnlocal/local.go | 2 +- logtail/logtail.go | 13 +++++++++++ logtail/logtail_test.go | 13 +++++++++++ types/logger/logger.go | 45 +++++++++++++++++++++++++++++++++++++ types/logger/logger_test.go | 11 +++++++++ 5 files changed, 83 insertions(+), 1 deletion(-) diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index cdfcbce61..1862988d9 100644 --- a/ipn/ipnlocal/local.go +++ b/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) diff --git a/logtail/logtail.go b/logtail/logtail.go index c0123e362..05acfc858 100644 --- a/logtail/logtail.go +++ b/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 } diff --git a/logtail/logtail_test.go b/logtail/logtail_test.go index 2ab5ab572..82cbd924c 100644 --- a/logtail/logtail_test.go +++ b/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) diff --git a/types/logger/logger.go b/types/logger/logger.go index 406b3a635..5ffc1418a 100644 --- a/types/logger/logger.go +++ b/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{}) diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index 14945105f..77c869e89 100644 --- a/types/logger/logger_test.go +++ b/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) + } +}