event: better printing
Change-Id: Ica914a861f7c174ccbba8de4234a0669f486248c
Reviewed-on: https://go-review.googlesource.com/c/exp/+/314949
Trust: Ian Cottrell <iancottrell@google.com>
Run-TryBot: Ian Cottrell <iancottrell@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
diff --git a/event/bench/event_test.go b/event/bench/event_test.go
index d98562b..4f0663c 100644
--- a/event/bench/event_test.go
+++ b/event/bench/event_test.go
@@ -123,43 +123,43 @@
func TestLogEventf(t *testing.T) {
testBenchmark(t, eventPrint, eventLogf, `
-2020/03/05 14:27:48 [1] log a where A=0
-2020/03/05 14:27:49 [2] log b where B="A value"
-2020/03/05 14:27:50 [3] log a where A=1
-2020/03/05 14:27:51 [4] log b where B="Some other value"
-2020/03/05 14:27:52 [5] log a where A=22
-2020/03/05 14:27:53 [6] log b where B="Some other value"
-2020/03/05 14:27:54 [7] log a where A=333
-2020/03/05 14:27:55 [8] log b where B=""
-2020/03/05 14:27:56 [9] log a where A=4444
-2020/03/05 14:27:57 [10] log b where B="prime count of values"
-2020/03/05 14:27:58 [11] log a where A=55555
-2020/03/05 14:27:59 [12] log b where B="V"
-2020/03/05 14:28:00 [13] log a where A=666666
-2020/03/05 14:28:01 [14] log b where B="A value"
-2020/03/05 14:28:02 [15] log a where A=7777777
-2020/03/05 14:28:03 [16] log b where B="A value"
+time=2020-03-05T14:27:48 id=1 kind=log msg="a where A=0"
+time=2020-03-05T14:27:49 id=2 kind=log msg="b where B=\"A value\""
+time=2020-03-05T14:27:50 id=3 kind=log msg="a where A=1"
+time=2020-03-05T14:27:51 id=4 kind=log msg="b where B=\"Some other value\""
+time=2020-03-05T14:27:52 id=5 kind=log msg="a where A=22"
+time=2020-03-05T14:27:53 id=6 kind=log msg="b where B=\"Some other value\""
+time=2020-03-05T14:27:54 id=7 kind=log msg="a where A=333"
+time=2020-03-05T14:27:55 id=8 kind=log msg="b where B=\"\""
+time=2020-03-05T14:27:56 id=9 kind=log msg="a where A=4444"
+time=2020-03-05T14:27:57 id=10 kind=log msg="b where B=\"prime count of values\""
+time=2020-03-05T14:27:58 id=11 kind=log msg="a where A=55555"
+time=2020-03-05T14:27:59 id=12 kind=log msg="b where B=\"V\""
+time=2020-03-05T14:28:00 id=13 kind=log msg="a where A=666666"
+time=2020-03-05T14:28:01 id=14 kind=log msg="b where B=\"A value\""
+time=2020-03-05T14:28:02 id=15 kind=log msg="a where A=7777777"
+time=2020-03-05T14:28:03 id=16 kind=log msg="b where B=\"A value\""
`)
}
func TestLogEvent(t *testing.T) {
testBenchmark(t, eventPrint, eventLog, `
-2020/03/05 14:27:48 [1] log a {"A":0}
-2020/03/05 14:27:49 [2] log b {"B":"A value"}
-2020/03/05 14:27:50 [3] log a {"A":1}
-2020/03/05 14:27:51 [4] log b {"B":"Some other value"}
-2020/03/05 14:27:52 [5] log a {"A":22}
-2020/03/05 14:27:53 [6] log b {"B":"Some other value"}
-2020/03/05 14:27:54 [7] log a {"A":333}
-2020/03/05 14:27:55 [8] log b {"B":""}
-2020/03/05 14:27:56 [9] log a {"A":4444}
-2020/03/05 14:27:57 [10] log b {"B":"prime count of values"}
-2020/03/05 14:27:58 [11] log a {"A":55555}
-2020/03/05 14:27:59 [12] log b {"B":"V"}
-2020/03/05 14:28:00 [13] log a {"A":666666}
-2020/03/05 14:28:01 [14] log b {"B":"A value"}
-2020/03/05 14:28:02 [15] log a {"A":7777777}
-2020/03/05 14:28:03 [16] log b {"B":"A value"}
+time=2020-03-05T14:27:48 id=1 kind=log msg=a A=0
+time=2020-03-05T14:27:49 id=2 kind=log msg=b B="A value"
+time=2020-03-05T14:27:50 id=3 kind=log msg=a A=1
+time=2020-03-05T14:27:51 id=4 kind=log msg=b B="Some other value"
+time=2020-03-05T14:27:52 id=5 kind=log msg=a A=22
+time=2020-03-05T14:27:53 id=6 kind=log msg=b B="Some other value"
+time=2020-03-05T14:27:54 id=7 kind=log msg=a A=333
+time=2020-03-05T14:27:55 id=8 kind=log msg=b B=""
+time=2020-03-05T14:27:56 id=9 kind=log msg=a A=4444
+time=2020-03-05T14:27:57 id=10 kind=log msg=b B="prime count of values"
+time=2020-03-05T14:27:58 id=11 kind=log msg=a A=55555
+time=2020-03-05T14:27:59 id=12 kind=log msg=b B=V
+time=2020-03-05T14:28:00 id=13 kind=log msg=a A=666666
+time=2020-03-05T14:28:01 id=14 kind=log msg=b B="A value"
+time=2020-03-05T14:28:02 id=15 kind=log msg=a A=7777777
+time=2020-03-05T14:28:03 id=16 kind=log msg=b B="A value"
`)
}
diff --git a/event/event.go b/event/event.go
index 5c26cd6..7e71918 100644
--- a/event/event.go
+++ b/event/event.go
@@ -6,9 +6,6 @@
import (
"fmt"
- "io"
- "strconv"
- "sync"
"time"
)
@@ -43,99 +40,9 @@
// Format prints the value in a standard form.
func (e *Event) Format(f fmt.State, verb rune) {
- buf := bufPool.Get().(*buffer)
- e.format(f.(writer), buf.data[:0])
- bufPool.Put(buf)
-}
-
-// Format prints the value in a standard form.
-func (e *Event) format(w writer, buf []byte) {
- const timeFormat = "2006/01/02 15:04:05"
- if !e.At.IsZero() {
- w.Write(e.At.AppendFormat(buf[:0], timeFormat))
- w.WriteString("\t")
- }
- //TODO: pick a standard format for the event id and parent
- w.WriteString("[")
- w.Write(strconv.AppendUint(buf[:0], e.ID, 10))
- if e.Parent != 0 {
- w.WriteString(":")
- w.Write(strconv.AppendUint(buf[:0], e.Parent, 10))
- }
- w.WriteString("]")
-
- //TODO: pick a standard format for the kind
- w.WriteString("\t")
- e.Kind.format(w, buf)
-
- if e.Message != "" {
- w.WriteString("\t")
- w.WriteString(e.Message)
- }
-
- first := true
- for _, l := range e.Labels {
- if l.Name == "" {
- continue
- }
- if first {
- w.WriteString("\t{")
- first = false
- } else {
- w.WriteString(", ")
- }
- l.format(w, buf)
- }
- if !first {
- w.WriteString("}")
- }
+ newPrinter(f).Event(e)
}
func (k Kind) Format(f fmt.State, verb rune) {
- buf := bufPool.Get().(*buffer)
- k.format(f.(writer), buf.data[:0])
- bufPool.Put(buf)
-}
-
-func (k Kind) format(w writer, buf []byte) {
- switch k {
- case LogKind:
- w.WriteString("log")
- case StartKind:
- w.WriteString("start")
- case EndKind:
- w.WriteString("end")
- case MetricKind:
- w.WriteString("metric")
- case AnnotateKind:
- w.WriteString("annotate")
- default:
- w.Write(strconv.AppendUint(buf[:0], uint64(k), 10))
- }
-}
-
-// Printer returns a handler that prints the events to the supplied writer.
-// Each event is printed in normal %v mode on its own line.
-func Printer(to io.Writer) Handler {
- return &printHandler{to: to}
-}
-
-type printHandler struct {
- to io.Writer
-}
-
-func (h *printHandler) Handle(ev *Event) {
- fmt.Fprintln(h.to, ev)
-}
-
-//TODO: some actual research into what this arbritray optimization number should be
-const bufCap = 50
-
-type buffer struct{ data [bufCap]byte }
-
-var bufPool = sync.Pool{New: func() interface{} { return new(buffer) }}
-
-type writer interface {
- io.Writer
- io.StringWriter
+ newPrinter(f).Kind(k)
}
diff --git a/event/event_test.go b/event/event_test.go
index 689858d..d26a6e4 100644
--- a/event/event_test.go
+++ b/event/event_test.go
@@ -30,19 +30,19 @@
}{{
name: "simple",
events: func(ctx context.Context) { event.To(ctx).Log("a message") },
- expect: `
-2020/03/05 14:27:48 [1] log a message
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message"
`}, {
name: "log 1",
events: func(ctx context.Context) { event.To(ctx).With(l1).Log("a message") },
- expect: `2020/03/05 14:27:48 [1] log a message {"l1":1}`}, {
- name: "simple",
- events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Log("a message") },
- expect: `2020/03/05 14:27:48 [1] log a message {"l1":1, "l2":2}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message" l1=1`,
}, {
- name: "simple",
+ name: "log 2",
+ events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Log("a message") },
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message" l1=1 l2=2`,
+ }, {
+ name: "log 3",
events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).With(l3).Log("a message") },
- expect: `2020/03/05 14:27:48 [1] log a message {"l1":1, "l2":2, "l3":3}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message" l1=1 l2=2 l3=3`,
}, {
name: "span",
events: func(ctx context.Context) {
@@ -50,8 +50,8 @@
end()
},
expect: `
-2020/03/05 14:27:48 [1] start span
-2020/03/05 14:27:49 [2:1] end
+time=2020-03-05T14:27:48 id=1 kind=start msg=span
+time=2020-03-05T14:27:49 id=2 span=1 kind=end
`}, {
name: "span nested",
events: func(ctx context.Context) {
@@ -62,27 +62,27 @@
event.To(child).Log("message")
},
expect: `
-2020/03/05 14:27:48 [1] start parent
-2020/03/05 14:27:49 [2:1] start child
-2020/03/05 14:27:50 [3:2] log message
-2020/03/05 14:27:51 [4:2] end
-2020/03/05 14:27:52 [5:1] end
+time=2020-03-05T14:27:48 id=1 kind=start msg=parent
+time=2020-03-05T14:27:49 id=2 span=1 kind=start msg=child
+time=2020-03-05T14:27:50 id=3 span=2 kind=log msg=message
+time=2020-03-05T14:27:51 id=4 span=2 kind=end
+time=2020-03-05T14:27:52 id=5 span=1 kind=end
`}, {
name: "metric",
events: func(ctx context.Context) { event.To(ctx).With(l1).Metric() },
- expect: `2020/03/05 14:27:48 [1] metric {"l1":1}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=metric l1=1`,
}, {
name: "metric 2",
events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Metric() },
- expect: `2020/03/05 14:27:48 [1] metric {"l1":1, "l2":2}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=metric l1=1 l2=2`,
}, {
name: "annotate",
events: func(ctx context.Context) { event.To(ctx).With(l1).Annotate() },
- expect: `2020/03/05 14:27:48 [1] annotate {"l1":1}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=annotate l1=1`,
}, {
name: "annotate 2",
events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Annotate() },
- expect: `2020/03/05 14:27:48 [1] annotate {"l1":1, "l2":2}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=annotate l1=1 l2=2`,
}, {
name: "multiple events",
events: func(ctx context.Context) {
@@ -91,8 +91,8 @@
b.With(keys.String("myString").Of("some string value")).Log("string event")
},
expect: `
-2020/03/05 14:27:48 [1] log my event {"myInt":6}
-2020/03/05 14:27:49 [2] log string event {"myString":"some string value"}
+time=2020-03-05T14:27:48 id=1 kind=log msg="my event" myInt=6
+time=2020-03-05T14:27:49 id=2 kind=log msg="string event" myString="some string value"
`}} {
buf := &strings.Builder{}
h := event.Printer(buf)
@@ -115,6 +115,6 @@
event.To(ctx).With(keys.Int("myInt").Of(6)).Log("my event")
event.To(ctx).With(keys.String("myString").Of("some string value")).Log("error event")
// Output:
- // 2020/03/05 14:27:48 [1] log my event {"myInt":6}
- // 2020/03/05 14:27:49 [2] log error event {"myString":"some string value"}
+ // time=2020-03-05T14:27:48 id=1 kind=log msg="my event" myInt=6
+ // time=2020-03-05T14:27:49 id=2 kind=log msg="error event" myString="some string value"
}
diff --git a/event/label.go b/event/label.go
index 6fab1e8..8011a2f 100644
--- a/event/label.go
+++ b/event/label.go
@@ -8,7 +8,6 @@
"fmt"
"math"
"reflect"
- "strconv"
"strings"
"unsafe"
)
@@ -43,43 +42,12 @@
// Format prints the label in a standard form.
func (l *Label) Format(f fmt.State, verb rune) {
- buf := bufPool.Get().(*buffer)
- l.format(f.(writer), buf.data[:0])
- bufPool.Put(buf)
-}
-
-func (l *Label) format(w writer, buf []byte) {
- w.Write(strconv.AppendQuote(buf[:0], l.Name))
- w.WriteString(":")
- l.Value.format(w, buf)
+ newPrinter(f).Label(l)
}
// Format prints the value in a standard form.
func (v *Value) Format(f fmt.State, verb rune) {
- buf := bufPool.Get().(*buffer)
- v.format(f.(writer), buf.data[:0])
- bufPool.Put(buf)
-}
-
-func (v *Value) format(w writer, buf []byte) {
- switch {
- case v.IsString():
- w.Write(strconv.AppendQuote(buf[:0], v.String()))
- case v.IsInt64():
- w.Write(strconv.AppendInt(buf[:0], v.Int64(), 10))
- case v.IsUint64():
- w.Write(strconv.AppendUint(buf[:0], v.Uint64(), 10))
- case v.IsFloat64():
- w.Write(strconv.AppendFloat(buf[:0], v.Float64(), 'g', -1, 64))
- case v.IsBool():
- if v.Bool() {
- w.WriteString("true")
- } else {
- w.WriteString("false")
- }
- default:
- fmt.Fprint(w, v.Interface())
- }
+ newPrinter(f).Value(v)
}
// HasValue returns true if the value is set to any type.
@@ -129,9 +97,7 @@
}
// not a string, so invoke the formatter to build one
w := &strings.Builder{}
- buf := bufPool.Get().(*buffer)
- v.format(w, buf.data[:0])
- bufPool.Put(buf)
+ newPrinter(w).Value(&v)
return w.String()
}
diff --git a/event/logfmt.go b/event/logfmt.go
new file mode 100644
index 0000000..1ea8566
--- /dev/null
+++ b/event/logfmt.go
@@ -0,0 +1,184 @@
+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package event
+
+import (
+ "fmt"
+ "io"
+ "strconv"
+)
+
+//TODO: some actual research into what this arbritray optimization number should be
+const bufCap = 50
+
+type printer struct {
+ io.Writer
+ io.StringWriter
+
+ buf [bufCap]byte
+}
+
+type stringWriter struct {
+ io.Writer
+}
+
+// Printer returns a handler that prints the events to the supplied writer.
+// Each event is printed in logfmt format on a single line.
+func Printer(to io.Writer) Handler {
+ return newPrinter(to)
+}
+
+func newPrinter(to io.Writer) *printer {
+ p := &printer{Writer: to}
+ ok := false
+ p.StringWriter, ok = to.(io.StringWriter)
+ if !ok {
+ p.StringWriter = &stringWriter{to}
+ }
+ return p
+}
+
+// Handle makes printer implement the Handler interface so it can be used
+// directly to print all handled events.
+func (p *printer) Handle(ev *Event) {
+ p.Event(ev)
+ p.WriteString("\n")
+}
+
+func (p *printer) Event(ev *Event) {
+ const timeFormat = "2006-01-02T15:04:05"
+ if !ev.At.IsZero() {
+ p.WriteString("time=")
+ p.Write(ev.At.AppendFormat(p.buf[:0], timeFormat))
+ p.WriteString(" ")
+ }
+
+ p.WriteString("id=")
+ p.Write(strconv.AppendUint(p.buf[:0], ev.ID, 10))
+ if ev.Parent != 0 {
+ p.WriteString(" span=")
+ p.Write(strconv.AppendUint(p.buf[:0], ev.Parent, 10))
+ }
+
+ p.WriteString(" kind=")
+ p.Kind(ev.Kind)
+
+ if ev.Message != "" {
+ p.WriteString(" msg=")
+ p.Quote(ev.Message)
+ }
+
+ for _, l := range ev.Labels {
+ if l.Name == "" {
+ continue
+ }
+ p.WriteString(" ")
+ p.Label(&l)
+ }
+}
+
+func (p *printer) Kind(k Kind) {
+ switch k {
+ case LogKind:
+ p.WriteString("log")
+ case StartKind:
+ p.WriteString("start")
+ case EndKind:
+ p.WriteString("end")
+ case MetricKind:
+ p.WriteString("metric")
+ case AnnotateKind:
+ p.WriteString("annotate")
+ default:
+ p.Write(strconv.AppendUint(p.buf[:0], uint64(k), 10))
+ }
+}
+
+func (p *printer) Label(l *Label) {
+ p.Ident(l.Name)
+ p.WriteString("=")
+ p.Value(&l.Value)
+}
+
+func (p *printer) Value(v *Value) {
+ switch {
+ case v.IsString():
+ p.Quote(v.String())
+ case v.IsInt64():
+ p.Write(strconv.AppendInt(p.buf[:0], v.Int64(), 10))
+ case v.IsUint64():
+ p.Write(strconv.AppendUint(p.buf[:0], v.Uint64(), 10))
+ case v.IsFloat64():
+ p.Write(strconv.AppendFloat(p.buf[:0], v.Float64(), 'g', -1, 64))
+ case v.IsBool():
+ if v.Bool() {
+ p.WriteString("true")
+ } else {
+ p.WriteString("false")
+ }
+ default:
+ fmt.Fprint(p, v.Interface())
+ }
+}
+
+func (p *printer) Ident(s string) {
+ //TODO: this should also escape = if it occurs in an ident?
+ p.Quote(s)
+}
+
+func (p *printer) Quote(s string) {
+ if s == "" {
+ p.WriteString(`""`)
+ return
+ }
+ if !needQuote(s) {
+ p.WriteString(s)
+ return
+ }
+ // string needs quoting
+ p.WriteString(`"`)
+ written := 0
+ for o, r := range s {
+ q := quoteRune(r)
+ if len(q) == 0 {
+ continue
+ }
+ // write out any prefix
+ p.WriteString(s[written:o])
+ written = o + 1 // we can plus 1 because all runes we escape are ascii
+ // and write out the quoted rune
+ p.WriteString(q)
+ }
+ p.WriteString(s[written:])
+ p.WriteString(`"`)
+}
+
+func needQuote(s string) bool {
+ for _, r := range s {
+ if len(quoteRune(r)) > 0 {
+ return true
+ }
+ }
+ return false
+}
+
+func quoteRune(r rune) string {
+ switch r {
+ case '"':
+ return `\"`
+ case ' ':
+ return ` ` // does not change but forces quoting
+ case '\n':
+ return `\n`
+ case '\\':
+ return `\\`
+ default:
+ return ``
+ }
+}
+
+func (w *stringWriter) WriteString(s string) (int, error) {
+ return w.Write([]byte(s))
+}
diff --git a/event/severity/severity_test.go b/event/severity/severity_test.go
index 01c1b05..22662a8 100644
--- a/event/severity/severity_test.go
+++ b/event/severity/severity_test.go
@@ -24,11 +24,11 @@
}{{
name: "debug",
events: func(ctx context.Context) { event.To(ctx).With(severity.Debug).Log("a message") },
- expect: `2020/03/05 14:27:48 [1] log a message {"level":debug}`,
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message" level=debug`,
}, {
name: "info",
events: func(ctx context.Context) { event.To(ctx).With(severity.Info).Log("a message") },
- expect: `2020/03/05 14:27:48 [1] log a message {"level":info}`},
+ expect: `time=2020-03-05T14:27:48 id=1 kind=log msg="a message" level=info`},
} {
buf := &strings.Builder{}
h := event.Printer(buf)
