Support fast Zap logging #366

mh-park · 2018-08-06T20:42:08Z

(This supersedes #361.)

This adds a zapcore.MarshalLogObject/Array method to all generated structs and its underlying components, enums, and non-primitive typedefs, implementing Zap marshalers (i.e. ObjectMarshaler, ArrayMarshaler). For typedefs of primitives, the logging is up to the user, simply by casting it down to the root type and using the respective Add/Append... method of the Zap encoder.

Sets and maps have nondeterministic behavior in iteration, but Zap logs/JSON has arrays that are orderly, causing issues in testing. Instead, we only write one element for those that are affected and test the loop logic separately in TestNondeterministicZapLogging.

abhinav · 2018-08-08T18:04:17Z

CHANGELOG.md

- No changes yet.
+- Added `zapcore.MarshalLogObject/Array` method to all generated structs 
+  and its underlying components, enums, and non-primitive typedefs, implementing 
+  Zap marshalers.


Let's change this to,

### Added - Generated types now implement zapcore.ObjectMarshaler or zapcore.ArrayMarshaler where appropriate. This should lead to much faster logging of these objects.

abhinav · 2018-08-08T18:06:47Z

gen/field.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2018 Uber Technologies, Inc.
+// Copyright (c) 2018 Uber Technologies, Inc


abhinav · 2018-08-08T18:09:12Z

gen/field.go

+						<- end ->
+					}
+				<- end>
+			<end>


nit: use <end -> for to end the range so that if .Fields is empty, we don't get an empty line.

abhinav · 2018-08-08T18:16:52Z

gen/field.go

+						<$encAdd>
+					<- end ->
+				<- else ->
+					<- $encAdd := printf "%s.Add%s(%q, %s)" $enc (zapEncoder .Type) .Name (zapMarshalerPtr .Type $fval) ->


I think we can reduce some of the duplication here with a TemplateFunc:

TemplateFunc("fieldMarshaler", func(required bool, t compile.TypeSpec, fval string) (string, error) { if required { return zapMarshaler(g, t, fval) } return zapMarshalerPtr(g, t, fval) })

Then the template becomes something like,

<- $encAdd := printf "%s.Add%s(%q, %s)" ... (fieldMarshaler .Required .Type $fval) -> <- if .Required -> <if (zapCanError .Type) -> ... <- else -> <$encAdd> <- end _> <- else -> ... <end>

abhinav · 2018-08-08T18:18:38Z

gen/field.go

+		func (<$v> *<.Name>) MarshalLogObject(<$enc> <$zapcore>.ObjectEncoder) error {
+			<range .Fields>
+				<- $fname := goName . ->
+				<- $fval := printf "%s.%s" $v $fname ->


nit: we can inline $fname in the $fval declaration

abhinav · 2018-08-08T18:32:40Z

gen/map.go

+		if err := g.EnsureDeclared(
+			`
+				type <.Name> <typeReference .Type>
+				<$zapcore := import "go.uber.org/zap/zapcore">


Imports at the top please

abhinav · 2018-08-08T18:37:45Z

gen/map.go

+						<- $encAdd := printf "%s.Add%s((string)(%s), %s)" $enc (zapEncoder .Type.ValueSpec) $k (zapMarshaler .Type.ValueSpec $v)>
+						<if (zapCanError .Type.ValueSpec) ->
+							if err := <$encAdd>; err != nil {
+								return err


Damn, this is getting repetitive. I wonder if we can clean up this err != nil business.

Can we maybe do something like,

<zapEncodeBegin .Type.ValueSpec> <$enc>.Add<zapEncoder ..>(..., <zapMarshaler .Type.ValueSpec $v>) <zapEncodeEnd .Type.ValueSpec>

Where zapEncodeBegin and zapEncodeEnd add the if err != nil, etc. if needed?

This will handle all these cases where we're doing if zapCanErr and
$errAdd again and again.

abhinav · 2018-08-08T18:41:55Z

gen/typedef.go

@@ -103,6 +103,26 @@ func typedef(g Generator, spec *compile.TypedefSpec) error {
 				return <equals .Target $lhs $rhs>
 			<- end>
 		}
+
+		<if (eq (zapEncoder .Target) "Object") ->


The template format supports template-level comments. Let's add a couple to explain what's going on here.

</* ... */>

abhinav · 2018-08-08T18:43:21Z

gen/typedef.go

+			<$enc := newVar "enc">
+			func (<$v> <$typedefType>) MarshalLogObject(<$enc> <$zapcore>.ObjectEncoder) error {
+				<if isStructType . ->
+					return ((<typeReference .Target>)(<$v>)).MarshalLogObject(<$enc>)


Isn't this case handled by zapMarshaler . $v too?

abhinav · 2018-08-08T18:44:46Z

gen/zap.go

+		*compile.StructSpec:
+		return true
+	}
+	panic(root)


Let's drop the panic. You can add checks for the true cases since there are
fewer of those and return false by default for all other cases.

Alternatively, you can also just call zapEncoder on the type and return true
only if the output is "Object" or "Array".

(If you do the zapEncodeBegin/zapEncodeEnd business, you can probably drop
this whole function.)

did you want to drop panic for the other functions as well?

For the cases we're doing exhaustive checks, let's keep the panic (but with a better error message).

For cases like this where it's more of an explicit list of things that can error out, we can just do catch-all for the false case rather than panicking.

This reverts the last 6 commits.

zapCanError has been replaced by zapEncodeBegin/zapEncodEnd. This allows a more readable template while achieving the same behavior.

abhinav

Minor issue with the map key's RootTypeSpec, but LGTM otherwise (besides nits).

abhinav · 2018-08-14T16:45:57Z

gen/type.go

@@ -193,6 +193,10 @@ func valueListName(g Generator, spec compile.TypeSpec) string {
 	return fmt.Sprintf("_%s_ValueList", g.MangleType(spec))
 }

+func zapperName(g Generator, spec compile.TypeSpec) string {


// zapperName returns the name that should be used for wrapper types that // implement zap.ObjectMarshaler or zap.ArrayMarshaler for the provided // Thrift type.

abhinav · 2018-08-14T18:15:14Z

gen/list.go

@@ -177,3 +181,40 @@ func (l *listGenerator) Equals(g Generator, spec *compile.ListSpec) (string, err

 	return name, wrapGenerateError(spec.ThriftName(), err)
 }
+
+func (l *listGenerator) zapMarshaler(


Let's document what we're logging things as.

// Slices are logged as JSON arrays.

abhinav · 2018-08-14T18:15:48Z

gen/map.go

@@ -281,3 +281,147 @@ func (m *mapGenerator) equalsUnhashable(g Generator, spec *compile.MapSpec) (str

 	return name, wrapGenerateError(spec.ThriftName(), err)
 }
+
+func (m *mapGenerator) zapMarshaler(


We should document this one in detail because it has non-obvious behavior.

// Maps are logged as objects if the key is a string or a typedef of a // string. If the key is not a string, maps are logged as arrays of // objects with a key and value. // // map[string]int32{"foo": 1, "bar": 2} // => {"foo": 1, "bar": 2} // // map[int32]string{1: "foo", 2: "bar"} // => [{"key": 1, "value": "foo"}, {"key": 2, "value": "bar"}]

abhinav · 2018-08-14T18:16:09Z

gen/list.go

+
+func (l *listGenerator) zapMarshaler(
+	g Generator,
+	root *compile.ListSpec,


nit: s/root/spec

In this context, there's only the "spec", no "root".

abhinav · 2018-08-14T18:23:06Z

gen/map.go

+		},
+	); err != nil {
+		return "", err
+	}


optional nit: can return err with the sprintf. There's no chance of that
panicking because name and fieldValue are strings (non-nillable).

err := g.EnsureDeclared(` ... `, ...) return fmt.Sprintf(...), err

abhinav · 2018-08-14T18:25:08Z

gen/map.go

+	g Generator,
+	keySpec compile.TypeSpec,
+	keyVar string,
+	valueSpec compile.TypeSpec,


optional: instead of passing keySpec and valueSpec, can pass in just the MapSpec.

abhinav · 2018-08-14T18:26:35Z

gen/map.go

+	valueSpec compile.TypeSpec,
+	valueVar string,
+) (string, error) {
+	name := fmt.Sprintf("_MapItem_%s_%s_Zapper", g.MangleType(keySpec), g.MangleType(valueSpec))


optional: can mangle the MapSpec and append _Item_Zapper to that instead.

abhinav · 2018-08-14T18:29:10Z

gen/zap.go

+
+	// Containers
+	case *compile.MapSpec:
+		switch t.KeySpec.(type) {


compile.RootTypeSpec(t.KeySpec) because the map key may be a typedef of a
string. If we don't have tests for this, we should add a test case to
typedefs.thrift.

abhinav · 2018-08-14T18:31:30Z

gen/zap.go

+// zapMarshaler takes a TypeSpec, evaluates whether there are underlying elements
+// that require more Zap implementation to log everything, and returns a string
+// that properly casts the fieldValue, if needed, for logging.
+func (z *zapGenerator) zapMarshaler(g Generator, spec compile.TypeSpec, fieldValue string) (string, error) {


Nice. Can you add,

// This should be used in conjunction with zapEncoder, // // v := ... // enc.Add<zapEncoder .Type>("foo", <zapMarshaler .Type "v">)

abhinav · 2018-08-14T18:32:29Z

gen/zap.go

+		// There is no AppendBinary for ArrayEncoder, so we opt for encoding it ourselves and
+		// appending it as a string. We also use AddString instead of AddBinary for ObjectEncoder
+		// for consistency.
+		base64 := g.Import("encoding/base64")


@akshayjshah FYI. All binary will be logged as base64. We will never rely on AddBinary because there's no AppendBinary.

akshayjshah

Looks great! Left some optional nits & questions, but I'm really excited about this.

akshayjshah · 2018-08-14T18:10:39Z

gen/map.go

+			func (<$m> <.Name>) MarshalLogObject(<$enc> <$zapcore>.ObjectEncoder) error {
+				for <$k>, <$v> := range <$m> {
+					<zapEncodeBegin .Type.ValueSpec ->
+						<$enc>.Add<zapEncoder .Type.ValueSpec>((string)(<$k>), <zapMarshaler .Type.ValueSpec $v>)


If $k is already a string, do we need the (string) here?

It may be a typedef of a string or a typedef of a typedef of a string.

akshayjshah · 2018-08-14T18:12:36Z

gen/enum.go

+				<range .UniqueItems ->
+					case <.Value>:
+						enc.AddString("name", "<.Name>")
+				<end ->


I assume that there's no default case in the switch because there's no safe default name, correct? If so, can we leave a comment in the generated code explaining that?

Quick update: Comments in the code aren't propagated by the templating logic
we have here. Godocs are propagated, though, so @mh-park added a comment about
how enums are serialized as a godoc.

akshayjshah · 2018-08-14T18:16:13Z

gen/list.go

+			func (<$l> <.Name>) MarshalLogArray(<$enc> <$zapcore>.ArrayEncoder) error {
+				for _, <$v> := range <$l> {
+					<zapEncodeBegin .Type.ValueSpec ->
+						<$enc>.Append<zapEncoder .Type.ValueSpec>(<zapMarshaler .Type.ValueSpec $v>)


@abhinav This is fine, but it has the minor downside of bailing out on the first error. This potentially leaves other errors lurking later in the array. How complex would it be to use multierr here and collect all the errors in one pass?

Completely fine if we leave this for a follow-up (or never do it).

I think it'll be a bit complex because of the different corner cases with some
encoders returning errors, some not.

I'll create a follow-up task to explore that in the future but for v1 of this,
we can skip it IMO.

akshayjshah · 2018-08-14T18:19:37Z

gen/map.go

+			// MarshalLogArray implements zapcore.ArrayMarshaler, enabling
+			// fast logging of <.Name>.
+			func (<$m> <.Name>) MarshalLogArray(<$enc> <$zapcore>.ArrayEncoder) error {
+				<- if isHashable .Type.KeySpec ->


😭 Thrift 😭

akshayjshah · 2018-08-14T18:26:57Z

gen/zap.go

+		// There is no AppendBinary for ArrayEncoder, so we opt for encoding it ourselves and
+		// appending it as a string. We also use AddString instead of AddBinary for ObjectEncoder
+		// for consistency.
+		base64 := g.Import("encoding/base64")


🤦‍♂️ My fault, noted this in uber-go/zap#388.

akshayjshah · 2018-08-14T18:48:33Z

@akshayjshah FYI. All binary will be logged as base64. We will never rely on AddBinary because there's no AppendBinary.

Concurrent review :) Yeah, this is totally my fault - I added a note to zap's 2.0 wishlist about this. For now, it's fine as-is.

This changes the generated MarshalLogObject for enums (thriftrw#366) to support the `go.label` annotation for enum items (thriftrw#363).

#366 added fast zap logging by generating extra `MarshalLog...` methods on generated types. For typedefs in thrift, other types that log them will cast to the underlying type in their `MarshalLog...` method, causing the generated code to need to import multiple go packages generated from both direct and indirect thrift dependencies. This should not be necessary, as typedefs of complex types (anything that cannot be mapped directly to a go stdlb type) get their own `MarshalLog...` methods, which cast to underlying type when necessary. This PR changes the logging for typedef'ed fields to: - cast to the underlying type inline when the underlying thrift type directly maps to a go type. - defer to the typedef's generated `MarshalLog...` method otherwise. This results in having more predictable importpaths (eg knowing that one thrift import will lead to one go import in generated code) makes implementing good bazel rules for thriftrw easier. See internal issue GO-362 for a more elaborate example of how the current behaviour complicates our Bazel setup.

#366 added fast zap logging by generating extra `MarshalLog...` methods on generated types. For typedefs in thrift, other types that log them will cast to the underlying type in their `MarshalLog...` method, causing the generated code to need to import multiple go packages generated from both direct and indirect thrift dependencies. This should not be necessary, as typedefs of complex types (anything that cannot be mapped directly to a go stdlib type) get their own `MarshalLog...` methods, which cast to underlying type when necessary. This PR changes the logging for typedef'ed fields to: - cast to the underlying type inline when the underlying thrift type directly maps to a go type. - defer to the typedef's generated `MarshalLog...` method otherwise. This results in having more predictable importpaths (eg knowing that one thrift import will lead to one go import in generated code) makes implementing good bazel rules for thriftrw easier. See internal issue GO-362 for a more elaborate example of how the current behaviour complicates our Bazel setup. Co-authored-by: Abhinav Gupta <abg@uber.com>

mh-park added 25 commits July 27, 2018 11:50

WIP: Zap logging support

373c29c

Add error handling for enc.{Add,Append}{Array,Object} for Zap logging

31f8d9c

Replace generated files with previous commit's change applied

7ebab96

Add comment placeholders

af51150

Add test files

cb70f07

Add Zap logging tests

eb6b1d7

Delete comments and add tests

7eeeaaf

Add testdata files

eb8c446

Drop go version 1.7/1.8 in travis

e886c90

Refactor Zap funcs

ba7e94e

Fix template spacing

169840e

Fix formatting and delete useless comments

6406b67

oops

dc47835

Add testdata

e0703a3

Update changelog

ac7fb4b

WIP

a3a379f

code review

323ec36

Add testdata

95c440c

wip

34c1a75

wip

7f0fe26

Refactor for readability

329ee0c

Fix styling

2328cac

glide: Pin to zap ^1

8eb048f

Modify changelog to reflect pr message

6b9f2b3

mh-park requested a review from abhinav August 6, 2018 20:42

abhinav reviewed Aug 8, 2018

View reviewed changes

mh-park added 3 commits August 8, 2018 14:02

Revert previous 6 commits

cebdda2

This reverts the last 6 commits.

Refactor ptr logic for readability

82eef82

zapCanError has been replaced by zapEncodeBegin/zapEncodEnd. This allows a more readable template while achieving the same behavior.

Add comments for anything confusing

cb3c11d

Code review

12b52c7

akshayjshah mentioned this pull request Aug 14, 2018

2.0 Wishlist uber-go/zap#388

Open

abhinav approved these changes Aug 14, 2018

View reviewed changes

akshayjshah mentioned this pull request Aug 14, 2018

Add Quoted Field Support uber-go/zap#600

Closed

3 tasks

akshayjshah approved these changes Aug 14, 2018

View reviewed changes

abhinav mentioned this pull request Aug 14, 2018

Logging: Record all errors #367

Closed

mh-park added 3 commits August 14, 2018 12:59

Code review + add test for map with typedef of string key

8bbf3aa

Add test files

4fbb43c

Add a comment about the default case for enums

77ad42b

abhinav merged commit 6cfc64a into dev Aug 14, 2018

abhinav deleted the minho/zap2 branch August 14, 2018 21:24

abhinav added a commit to cl1337/thriftrw-go that referenced this pull request Aug 14, 2018

enum: MarshalLogObject should support go.label

ba9c0a0

This changes the generated MarshalLogObject for enums (thriftrw#366) to support the `go.label` annotation for enum items (thriftrw#363).

abhinav mentioned this pull request Aug 15, 2018

Release 1.13.0 #372

Closed

11 tasks

robbertvanginkel mentioned this pull request Feb 10, 2021

Remove inline typeconvert when logging some thrift typedefs #464

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Support fast Zap logging #366

Support fast Zap logging #366

mh-park commented Aug 6, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

abhinav Aug 8, 2018

mh-park Aug 8, 2018

abhinav Aug 8, 2018

abhinav left a comment

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

akshayjshah left a comment

akshayjshah Aug 14, 2018

abhinav Aug 14, 2018

akshayjshah Aug 14, 2018

abhinav Aug 14, 2018

abhinav Aug 14, 2018

akshayjshah Aug 14, 2018

abhinav Aug 14, 2018

akshayjshah Aug 14, 2018

akshayjshah Aug 14, 2018

akshayjshah commented Aug 14, 2018

		@@ -1,4 +1,4 @@
		// Copyright (c) 2018 Uber Technologies, Inc.
		// Copyright (c) 2018 Uber Technologies, Inc

Support fast Zap logging #366

Support fast Zap logging #366

Conversation

mh-park commented Aug 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhinav left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah commented Aug 14, 2018