Log error fields as tags (cadence-workflow#4801)

* Log error fields as tags * Update common/log/loggerimpl/logger.go Co-authored-by: Steven L <[email protected]> * Fix syntax error * Use zap ObjectMarshaler for nested fields Co-authored-by: Steven L <[email protected]>
avmi · May 11, 2022 · a51b613 · a51b613
1 parent eede466
commit a51b613
Show file tree

Hide file tree

Showing 12 changed files with 127 additions and 109 deletions.
diff --git a/common/elasticsearch/validator/queryValidator_test.go b/common/elasticsearch/validator/queryValidator_test.go
@@ -59,32 +59,32 @@ func TestValidateQuery(t *testing.T) {
 		{
 			msg:   "invalid SQL",
 			query: "Invalid SQL",
-			err:   "BadRequestError{Message: Invalid query.}",
+			err:   "Invalid query.",
 		},
 		{
 			msg:   "invalid where expression",
 			query: "InvalidWhereExpr",
-			err:   "BadRequestError{Message: invalid where clause}",
+			err:   "invalid where clause",
 		},
 		{
 			msg:   "invalid comparison",
 			query: "WorkflowID = 'wid' and 1 < 2",
-			err:   "BadRequestError{Message: invalid comparison expression}",
+			err:   "invalid comparison expression",
 		},
 		{
 			msg:   "invalid range",
 			query: "1 between 1 and 2 or WorkflowID = 'wid'",
-			err:   "BadRequestError{Message: invalid range expression}",
+			err:   "invalid range expression",
 		},
 		{
 			msg:   "invalid search attribute in comparison",
 			query: "Invalid = 'a' and 1 < 2",
-			err:   "BadRequestError{Message: invalid search attribute}",
+			err:   "invalid search attribute",
 		},
 		{
 			msg:   "invalid search attribute in range",
 			query: "Invalid between 1 and 2 or WorkflowID = 'wid'",
-			err:   "BadRequestError{Message: invalid search attribute}",
+			err:   "invalid search attribute",
 		},
 		{
 			msg:       "only order by",
@@ -104,27 +104,27 @@ func TestValidateQuery(t *testing.T) {
 		{
 			msg:   "invalid order by attribute",
 			query: "order by InvalidField desc",
-			err:   "BadRequestError{Message: invalid order by attribute}",
+			err:   "invalid order by attribute",
 		},
 		{
 			msg:   "invalid order by attribute expr",
 			query: "order by 123",
-			err:   "BadRequestError{Message: invalid order by expression}",
+			err:   "invalid order by expression",
 		},
 		{
 			msg:   "security SQL injection - with another statement",
 			query: "WorkflowID = 'wid'; SELECT * FROM important_table;",
-			err:   "BadRequestError{Message: Invalid query.}",
+			err:   "Invalid query.",
 		},
 		{
 			msg:   "security SQL injection - with always true expression",
 			query: "WorkflowID = 'wid' and (RunID = 'rid' or 1 = 1)",
-			err:   "BadRequestError{Message: invalid comparison expression}",
+			err:   "invalid comparison expression",
 		},
 		{
 			msg:   "security SQL injection - with union",
 			query: "WorkflowID = 'wid' union select * from dummy",
-			err:   "BadRequestError{Message: Invalid select query.}",
+			err:   "Invalid select query.",
 		},
 	}
 

diff --git a/common/elasticsearch/validator/searchAttrValidator_test.go b/common/elasticsearch/validator/searchAttrValidator_test.go
@@ -73,22 +73,22 @@ func (s *searchAttributesValidatorSuite) TestValidateSearchAttributes() {
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal("BadRequestError{Message: number of keys 3 exceed limit}", err.Error())
+	s.Equal("number of keys 3 exceed limit", err.Error())
 
 	fields = map[string][]byte{
 		"InvalidKey": []byte(`"1"`),
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal(`BadRequestError{Message: InvalidKey is not a valid search attribute key}`, err.Error())
+	s.Equal(`InvalidKey is not a valid search attribute key`, err.Error())
 
 	fields = map[string][]byte{
 		"CustomStringField": []byte(`"1"`),
 		"CustomBoolField":   []byte(`123`),
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal(`BadRequestError{Message: 123 is not a valid search attribute value for key CustomBoolField}`, err.Error())
+	s.Equal(`123 is not a valid search attribute value for key CustomBoolField`, err.Error())
 
 	fields = map[string][]byte{
 		"CustomIntField": []byte(`[1,2]`),
@@ -102,20 +102,20 @@ func (s *searchAttributesValidatorSuite) TestValidateSearchAttributes() {
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal(`BadRequestError{Message: StartTime is read-only Cadence reservered attribute}`, err.Error())
+	s.Equal(`StartTime is read-only Cadence reservered attribute`, err.Error())
 
 	fields = map[string][]byte{
 		"CustomKeywordField": []byte(`"123456"`),
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal(`BadRequestError{Message: size limit exceed for key CustomKeywordField}`, err.Error())
+	s.Equal(`size limit exceed for key CustomKeywordField`, err.Error())
 
 	fields = map[string][]byte{
 		"CustomKeywordField": []byte(`"123"`),
 		"CustomStringField":  []byte(`"12"`),
 	}
 	attr.IndexedFields = fields
 	err = validator.ValidateSearchAttributes(attr, domain)
-	s.Equal(`BadRequestError{Message: total size 44 exceed limit}`, err.Error())
+	s.Equal(`total size 44 exceed limit`, err.Error())
 }
diff --git a/common/log/loggerimpl/logger.go b/common/log/loggerimpl/logger.go
@@ -27,6 +27,7 @@ import (
 
 	"github.com/stretchr/testify/suite"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"go.uber.org/zap/zaptest"
 
 	"github.com/uber/cadence/common/log"
@@ -96,6 +97,10 @@ func (lg *loggerImpl) buildFields(tags []tag.Tag) []zap.Field {
 			continue
 		}
 		fs = append(fs, f)
+
+		if obj, ok := f.Interface.(zapcore.ObjectMarshaler); ok && f.Type == zapcore.ErrorType {
+			fs = append(fs, zap.Object(f.Key+"-details", obj))
+		}
 	}
 	return fs
 }

diff --git a/common/log/loggerimpl/logger_test.go b/common/log/loggerimpl/logger_test.go
@@ -31,6 +31,7 @@ import (
 
 	"github.com/stretchr/testify/assert"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 
 	"github.com/uber/cadence/common/dynamicconfig"
 	"github.com/uber/cadence/common/log/tag"
@@ -132,3 +133,25 @@ func TestEmptyMsg(t *testing.T) {
 	assert.Equal(t, out, `{"level":"info","msg":"`+defaultMsgForEmpty+`","error":"test error","wf-action":"add-workflow-started-event","logging-call-at":"logger_test.go:`+lineNum+`"}`+"\n")
 
 }
+
+func TestErrorWithDetails(t *testing.T) {
+	sb := &strings.Builder{}
+	zapLogger := zap.New(zapcore.NewCore(zapcore.NewJSONEncoder(zapcore.EncoderConfig{MessageKey: "msg"}), zapcore.AddSync(sb), zap.DebugLevel))
+	logger := NewLogger(zapLogger)
+
+	err := &testError{"workflow123"}
+	logger.Error("oh no", tag.Error(err))
+	zapLogger.Sync()
+
+	assert.Contains(t, sb.String(), `"msg":"oh no","error":"test error","error-details":{"workflow-id":"workflow123"}`)
+}
+
+type testError struct {
+	WorkflowId string
+}
+
+func (e testError) Error() string { return "test error" }
+func (e testError) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddString("workflow-id", e.WorkflowId)
+	return nil
+}
diff --git a/common/log/tag/tags.go b/common/log/tag/tags.go
@@ -202,16 +202,6 @@ func WorkflowNextEventID(nextEventID int64) Tag {
 	return newInt64("wf-next-event-id", nextEventID)
 }
 
-// WorkflowBeginningFirstEventID returns tag for WorkflowBeginningFirstEventID
-func WorkflowBeginningFirstEventID(beginningFirstEventID int64) Tag {
-	return newInt64("wf-begining-first-event-id", beginningFirstEventID)
-}
-
-// WorkflowEndingNextEventID returns tag for WorkflowEndingNextEventID
-func WorkflowEndingNextEventID(endingNextEventID int64) Tag {
-	return newInt64("wf-ending-next-event-id", endingNextEventID)
-}
-
 // WorkflowResetNextEventID returns tag for WorkflowResetNextEventID
 func WorkflowResetNextEventID(resetNextEventID int64) Tag {
 	return newInt64("wf-reset-next-event-id", resetNextEventID)

diff --git a/common/reconciliation/invariant/historyExists_test.go b/common/reconciliation/invariant/historyExists_test.go
@@ -88,7 +88,7 @@ func (s *HistoryExistsSuite) TestCheck() {
 				CheckResultType: CheckResultTypeCorrupted,
 				InvariantName:   HistoryExists,
 				Info:            "concrete execution exists but history does not exist",
-				InfoDetails:     "EntityNotExistsError{Message: got entity not exists error}",
+				InfoDetails:     "got entity not exists error",
 			},
 			expectedResourcePopulated: false,
 		},

diff --git a/common/reconciliation/invariant/openCurrentExecution_test.go b/common/reconciliation/invariant/openCurrentExecution_test.go
@@ -107,7 +107,7 @@ func (s *OpenCurrentExecutionSuite) TestCheck() {
 				CheckResultType: CheckResultTypeCorrupted,
 				InvariantName:   OpenCurrentExecution,
 				Info:            "execution is open without having current execution",
-				InfoDetails:     "EntityNotExistsError{Message: }",
+				InfoDetails:     "",
 			},
 		},
 		{