diff --git a/common/errors/errors.go b/common/errors/errors.go index 920ec4bebfb..2c96eb41894 100644 --- a/common/errors/errors.go +++ b/common/errors/errors.go @@ -23,7 +23,6 @@ import ( "regexp" "runtime" - "github.com/hyperledger/fabric/common/flogging" logging "github.com/op/go-logging" ) @@ -73,9 +72,18 @@ func setupCallError(e *callError, generateStack bool) { e.stack = stack[:length] } -// Error comes from the error interface +// Error comes from the error interface - it returns the error message and +// appends the callstack, if available func (e *callError) Error() string { - return e.Message() + message := e.GetErrorCode() + " - " + fmt.Sprintf(e.message, e.args...) + // check that the error has a callstack before proceeding + if e.GetStack() != "" { + message = appendCallStack(message, e.GetStack()) + } + if e.prevErr != nil { + message += "\nCaused by: " + e.prevErr.Error() + } + return message } // GetStack returns the call stack as a string @@ -102,18 +110,14 @@ func (e *callError) GetErrorCode() string { // language. func (e *callError) Message() string { message := e.GetErrorCode() + " - " + fmt.Sprintf(e.message, e.args...) - // check that the error has a callstack before proceeding - if e.GetStack() != "" { - // stacktrace is enabled when `logging.error` in core.yaml is set to - // DEBUG. it can also be toggled for code running on the peer dynamically - // via CLI using `peer logging setlevel error ` - errorLevel := flogging.GetModuleLevel("error") - if errorLevel == logging.DEBUG.String() { - message = appendCallStack(message, e.GetStack()) - } - } + if e.prevErr != nil { - message += "\nCaused by: " + e.prevErr.Error() + switch previousError := e.prevErr.(type) { + case CallStackError: + message += "\nCaused by: " + previousError.Message() + default: + message += "\nCaused by: " + e.prevErr.Error() + } } return message } diff --git a/common/errors/errors_test.go b/common/errors/errors_test.go index 2dbd906bc1b..b67f14a2c46 100644 --- a/common/errors/errors_test.go +++ b/common/errors/errors_test.go @@ -19,137 +19,106 @@ package errors import ( "fmt" - "strings" "testing" - "github.com/hyperledger/fabric/common/flogging" + "github.com/stretchr/testify/assert" ) -func TestError(t *testing.T) { - e := Error("UNK", "404", "An unknown error occurred.") - s := e.GetStack() - if s != "" { - t.Fatalf("No error stack should have been recorded.") - } -} - -// TestErrorWithArg tests creating an error with a message argument -func TestErrorWithArg(t *testing.T) { - e := Error("UNK", "405", "An error occurred: %s", "arg1") - s := e.GetStack() - if s != "" { - t.Fatalf("No error stack should have been recorded.") - } -} - -func TestErrorWithCallstack(t *testing.T) { - e := ErrorWithCallstack("UNK", "404", "An unknown error occurred.") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack was recorded.") - } -} - -func TestErrorWithCallstack_wrapped(t *testing.T) { - e := ErrorWithCallstack("UNK", "404", "An unknown error occurred.") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack was recorded.") - } - - e2 := ErrorWithCallstack("CHA", "404", "An unknown error occurred.").WrapError(e) - s2 := e2.GetStack() - if s2 == "" { - t.Fatalf("No error stack was recorded.") - } -} - -// TestErrorWithCallstackAndArg tests creating an error with a callstack and -// message argument -func TestErrorWithCallstackAndArg(t *testing.T) { - e := ErrorWithCallstack("UNK", "405", "An error occurred: %s", "arg1") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack was recorded.") - } -} - -func TestErrorWithCallstackAndArg_wrappedNoCallstack(t *testing.T) { - e := Error("UNK", "405", "An error occurred: %s", "arg1") - s := e.GetStack() - if s != "" { - t.Fatalf("No error stack should have been recorded.") - } - - e2 := ErrorWithCallstack("CHA", "404", "An error occurred: %s", "anotherarg1").WrapError(e) - s2 := e2.GetStack() - if s2 == "" { - t.Fatalf("No error stack was recorded.") - } -} - -func TestError_wrappedWithCallstackAndArg(t *testing.T) { - e := ErrorWithCallstack("UNK", "405", "An error occurred: %s", "arg1") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack should have been recorded.") - } - - e2 := Error("CHA", "404", "An error occurred: %s", "anotherarg1").WrapError(e) - s2 := e2.GetStack() - if s2 != "" { - t.Fatalf("No error stack was recorded.") - } +type testCase struct { + name string + errorArgs []string + messageArgs []string + wrappedErrorArgs []string + wrappedMessageArgs []string + generateStack []bool } -// TestErrorWithCallstackMessage tests the output for a logging error where -// and an invalid log level has been provided and the stack trace should be -// displayed with the error message -func TestErrorWithCallstackMessage(t *testing.T) { - // when the 'error' module is set to debug, the callstack will be appended - // to the error message - flogging.SetModuleLevel("error", "debug") - - e := ErrorWithCallstack("UNK", "405", "An unknown error occurred.") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack was recorded.") - } - - // check that the error message contains this part of the stack trace, which - // is non-platform specific - if !strings.Contains(e.Error(), "github.com/hyperledger/fabric/common/errors.TestErrorWithCallstackMessage") { - t.Fatalf("Error message does not have stack trace appended.") - } -} - -func TestErrorWithCallstackMessage_wrapped(t *testing.T) { - // when the 'error' module is set to debug, the callstack will be appended - // to the error message - flogging.SetModuleLevel("error", "debug") - - e := ErrorWithCallstack("UNK", "405", "An error occurred: %s", "arg1") - s := e.GetStack() - if s == "" { - t.Fatalf("No error stack was recorded.") - } - - // check that the error message contains this part of the stack trace, which - // is non-platform specific - if !strings.Contains(e.Error(), "github.com/hyperledger/fabric/common/errors.TestErrorWithCallstackMessage_wrapped") { - t.Fatalf("Error message does not have stack trace appended.") - } - - e2 := ErrorWithCallstack("CHA", "405", "A chaincode error occurred: %s", "ccarg1").WrapError(e) - s2 := e2.GetStack() - if s2 == "" { - t.Fatalf("No error stack was recorded.") - } - - // check that the error message contains this part of the stack trace, which - // is non-platform specific - if !strings.Contains(e2.Error(), "github.com/hyperledger/fabric/common/errors.TestErrorWithCallstackMessage_wrapped") { - t.Fatalf("Error message does not have stack trace appended.") +func TestError(t *testing.T) { + var tc []testCase + + tc = append(tc, + testCase{"UnknownErrorWithCallstack", []string{"UNK", "404", "An unknown error occurred."}, nil, nil, nil, []bool{true}}, + testCase{"UnknownError", []string{"UNK", "404", "An unknown error occurred."}, nil, nil, nil, []bool{false}}, + testCase{"UnknownErrorWithCallstackAndArg", []string{"UNK", "405", "An error occurred: %s"}, []string{"arg1"}, nil, nil, []bool{true}}, + testCase{"UnknownErrorWithArg", []string{"UNK", "405", "An error occurred: %s"}, []string{"arg1"}, nil, nil, []bool{false}}, + testCase{"CallStackErrorWrappedCallstackError", []string{"CHA", "404", "An unknown error occurred."}, nil, []string{"UNK", "404", "An unknown error occurred."}, nil, []bool{true, true}}, + testCase{"ErrorWrappedError", []string{"CHA", "404", "An unknown error occurred."}, nil, []string{"UNK", "404", "An unknown error occurred."}, nil, []bool{false, false}}, + testCase{"CallStackErrorWrappedError", []string{"CHA", "404", "An unknown error occurred."}, nil, []string{"UNK", "404", "An unknown error occurred."}, nil, []bool{true, false}}, + testCase{"ErrorWrappedCallStackError", []string{"CHA", "404", "An unknown error occurred."}, nil, []string{"UNK", "404", "An unknown error occurred."}, nil, []bool{false, true}}, + testCase{"ErrorWrappedStandardError", []string{"CHA", "404", "An unknown error occurred."}, nil, []string{"grpc timed out: %s"}, []string{"failed to connect to server"}, []bool{false, true}}, + ) + + assert := assert.New(t) + + for i := 0; i < len(tc); i++ { + t.Run(tc[i].name, func(t *testing.T) { + var err, wrappedErr CallStackError + var wrappedStandardError error + + // generate callstack + if tc[i].generateStack[0] { + if tc[i].messageArgs != nil { + err = ErrorWithCallstack(tc[i].errorArgs[0], tc[i].errorArgs[1], tc[i].errorArgs[2], tc[i].messageArgs) + } else { + err = ErrorWithCallstack(tc[i].errorArgs[0], tc[i].errorArgs[1], tc[i].errorArgs[2]) + } + assert.NotEqual("", err.GetStack(), "Test case '%s' failed", tc[i].name) + assert.Contains(err.Error(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + } else { + if tc[i].messageArgs != nil { + err = Error(tc[i].errorArgs[0], tc[i].errorArgs[1], tc[i].errorArgs[2], tc[i].messageArgs) + } else { + err = Error(tc[i].errorArgs[0], tc[i].errorArgs[1], tc[i].errorArgs[2]) + } + assert.Equal("", err.GetStack(), "Test case '%s' failed", tc[i].name) + assert.NotContains(err.Error(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + } + assert.Equal(tc[i].errorArgs[0], err.GetComponentCode(), "Test case '%s' failed", tc[i].name) + assert.Equal(tc[i].errorArgs[1], err.GetReasonCode(), "Test case '%s' failed", tc[i].name) + if tc[i].messageArgs != nil { + assert.Contains(err.Error(), fmt.Sprintf(tc[i].errorArgs[2], tc[i].messageArgs), "Test case '%s' failed", tc[i].name) + } else { + assert.Contains(err.Error(), tc[i].errorArgs[2], "Test case '%s' failed", tc[i].name) + } + assert.NotContains(err.Message(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + + if tc[i].wrappedErrorArgs != nil { + if len(tc[i].wrappedErrorArgs) == 3 { + if tc[i].generateStack[1] { + if tc[i].wrappedMessageArgs != nil { + wrappedErr = ErrorWithCallstack(tc[i].wrappedErrorArgs[0], tc[i].wrappedErrorArgs[1], tc[i].wrappedErrorArgs[2], tc[i].wrappedMessageArgs) + } else { + wrappedErr = ErrorWithCallstack(tc[i].wrappedErrorArgs[0], tc[i].wrappedErrorArgs[1], tc[i].wrappedErrorArgs[2]) + } + assert.NotEqual("", wrappedErr.GetStack(), "Test case '%s' failed", tc[i].name) + assert.Contains(wrappedErr.Error(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + } else { + if tc[i].wrappedMessageArgs != nil { + wrappedErr = Error(tc[i].wrappedErrorArgs[0], tc[i].wrappedErrorArgs[1], tc[i].wrappedErrorArgs[2], tc[i].wrappedMessageArgs) + } else { + wrappedErr = Error(tc[i].wrappedErrorArgs[0], tc[i].wrappedErrorArgs[1], tc[i].wrappedErrorArgs[2]) + } + assert.Equal("", wrappedErr.GetStack(), "Test case '%s' failed", tc[i].name) + assert.NotContains(wrappedErr.Error(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + } + assert.Equal(tc[i].wrappedErrorArgs[0], wrappedErr.GetComponentCode(), "Test case '%s' failed", tc[i].name) + assert.Equal(tc[i].wrappedErrorArgs[1], wrappedErr.GetReasonCode(), "Test case '%s' failed", tc[i].name) + err = err.WrapError(wrappedErr) + if tc[i].wrappedMessageArgs != nil { + assert.Contains(err.Error(), fmt.Sprintf(tc[i].wrappedErrorArgs[2], tc[i].wrappedMessageArgs), "Test case '%s' failed", tc[i].name) + } else { + assert.Contains(err.Error(), tc[i].wrappedErrorArgs[2], "Test case '%s' failed", tc[i].name) + } + } else { + wrappedStandardError = fmt.Errorf(tc[i].wrappedErrorArgs[0], tc[i].wrappedMessageArgs) + err = err.WrapError(wrappedStandardError) + assert.Contains(err.Error(), fmt.Sprintf(tc[i].wrappedErrorArgs[0], tc[i].wrappedMessageArgs), "Test case '%s' failed", tc[i].name) + + } + assert.Contains(err.Error(), "Caused by:", "Test case '%s' failed", tc[i].name) + assert.NotContains(err.Message(), "github.com/hyperledger/fabric/common/errors", "Test case '%s' failed", tc[i].name) + } + }) } } @@ -183,178 +152,3 @@ func TestIsValidComponentOrReasonCode(t *testing.T) { } } - -func ExampleError() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - err := Error("UNK", "404", "An unknown error occurred.") - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // UNK:404 - An unknown error occurred. - // UNK:404 - // UNK - // 404 - // UNK:404 - An unknown error occurred. - } -} - -func ExampleErrorWithCallstack() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - err := ErrorWithCallstack("UNK", "404", "An unknown error occurred.") - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // UNK:404 - An unknown error occurred. - // UNK:404 - // UNK - // 404 - // UNK:404 - An unknown error occurred. - } -} - -// Example_utilityErrorWithArg tests the output for a sample error with a message -// argument -func Example_utilityErrorWithArg() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - err := ErrorWithCallstack("UNK", "405", "An error occurred: %s", "arg1") - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // UNK:405 - An error occurred: arg1 - // UNK:405 - // UNK - // 405 - // UNK:405 - An error occurred: arg1 - } -} - -// Example_wrappedUtilityErrorWithArg tests the output for a CallStackError -// with message argument that is wrapped into another error. -func Example_wrappedUtilityErrorWithArg() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - wrappedErr := ErrorWithCallstack("UNK", "405", "An error occurred: %s", "arg1") - err := ErrorWithCallstack("CHA", "500", "Utility error occurred: %s", "ccarg1").WrapError(wrappedErr) - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // CHA:500 - Utility error occurred: ccarg1 - // Caused by: UNK:405 - An error occurred: arg1 - // CHA:500 - // CHA - // 500 - // CHA:500 - Utility error occurred: ccarg1 - // Caused by: UNK:405 - An error occurred: arg1 - } -} - -// Example_wrappedStandardError tests the output for a standard error -// with message argument that is wrapped into a CallStackError. -func Example_wrappedStandardError() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - wrappedErr := fmt.Errorf("grpc timed out: %s", "failed to connect to server") - err := ErrorWithCallstack("CHA", "500", "Error sending message: %s", "invoke").WrapError(wrappedErr) - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // CHA:500 - Error sending message: invoke - // Caused by: grpc timed out: failed to connect to server - // CHA:500 - // CHA - // 500 - // CHA:500 - Error sending message: invoke - // Caused by: grpc timed out: failed to connect to server - } -} - -// Example_wrappedStandardError2 tests the output for CallStackError wrapped -// into a standard error with message argument that is wrapped into a -// CallStackError. -func Example_wrappedStandardError2() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - wrappedErr := ErrorWithCallstack("CON", "500", "failed to connect to server") - wrappedErr2 := fmt.Errorf("grpc timed out: %s", wrappedErr) - err := ErrorWithCallstack("CHA", "500", "Error sending message: %s", "invoke").WrapError(wrappedErr2) - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // CHA:500 - Error sending message: invoke - // Caused by: grpc timed out: CON:500 - failed to connect to server - // CHA:500 - // CHA - // 500 - // CHA:500 - Error sending message: invoke - // Caused by: grpc timed out: CON:500 - failed to connect to server - } -} - -// Example_loggingInvalidLevel tests the output for a logging error where -// and an invalid log level has been provided -func Example_loggingInvalidLevel() { - // when the 'error' module is set to anything but debug, the callstack will - // not be appended to the error message - flogging.SetModuleLevel("error", "warning") - - err := ErrorWithCallstack("LOG", "400", "Invalid log level provided - %s", "invalid") - - if err != nil { - fmt.Printf("%s\n", err.Error()) - fmt.Printf("%s\n", err.GetErrorCode()) - fmt.Printf("%s\n", err.GetComponentCode()) - fmt.Printf("%s\n", err.GetReasonCode()) - fmt.Printf("%s\n", err.Message()) - // Output: - // LOG:400 - Invalid log level provided - invalid - // LOG:400 - // LOG - // 400 - // LOG:400 - Invalid log level provided - invalid - } -} diff --git a/common/flogging/logging.go b/common/flogging/logging.go index 8c2204a60b7..f4f0b8d7513 100644 --- a/common/flogging/logging.go +++ b/common/flogging/logging.go @@ -93,11 +93,6 @@ func GetModuleLevel(module string) string { // regular expression. Can be used to dynamically change the log level for the // module. func SetModuleLevel(moduleRegExp string, level string) (string, error) { - // special case - `error` module, which is used to enable/disable callstacks - // in error messages, shouldn't use regular expressions - if moduleRegExp == "error" { - return setModuleLevel(moduleRegExp, level, false, false) - } return setModuleLevel(moduleRegExp, level, true, false) } diff --git a/peer/clilogging/logging.go b/peer/clilogging/logging.go index 1652db1aa7e..a69eac3eaf6 100644 --- a/peer/clilogging/logging.go +++ b/peer/clilogging/logging.go @@ -20,7 +20,6 @@ import ( "fmt" "github.com/hyperledger/fabric/common/flogging" - "github.com/hyperledger/fabric/peer/common" "github.com/spf13/cobra" ) @@ -39,18 +38,7 @@ func Cmd() *cobra.Command { } var loggingCmd = &cobra.Command{ - Use: loggingFuncName, - PersistentPreRunE: func(cmd *cobra.Command, args []string) error { - // initialize the log level for the "error" module to the value of - // logging.error in core.yaml. this is necessary to ensure that these - // logging CLI commands, which execute outside of the peer, can - // automatically append the stack trace to the error message (if set to - // debug). - // note: for code running on the peer, this level is set during peer startup - // in peer/node/start.go and can be updated dynamically using - // "peer logging setlevel error " - return common.SetLogLevelFromViper("error") - }, + Use: loggingFuncName, Short: fmt.Sprintf("%s specific commands.", loggingFuncName), Long: fmt.Sprintf("%s specific commands.", loggingFuncName), } diff --git a/peer/common/common.go b/peer/common/common.go index 7539b3df06d..effdb644f12 100644 --- a/peer/common/common.go +++ b/peer/common/common.go @@ -94,14 +94,7 @@ func SetLogLevelFromViper(module string) error { logLevelFromViper := viper.GetString("logging." + module) err = CheckLogLevel(logLevelFromViper) if err != nil { - if module == "error" { - // if 'logging.error' not found in core.yaml or an invalid level has - // been entered, set default to debug to ensure the callstack is - // appended to all CallStackErrors - logLevelFromViper = "debug" - } else { - return err - } + return err } _, err = flogging.SetModuleLevel(module, logLevelFromViper) } diff --git a/peer/node/start.go b/peer/node/start.go index 1d290c448b0..9cb4fcfbb46 100644 --- a/peer/node/start.go +++ b/peer/node/start.go @@ -81,10 +81,6 @@ var nodeStartCmd = &cobra.Command{ Short: "Starts the node.", Long: `Starts a node that interacts with the network.`, RunE: func(cmd *cobra.Command, args []string) error { - // initialize the log level for the "error" module to the value of - // `logging.error` in core.yaml. this is necessary to ensure that the stack - // is automatically appended to error messages (if set to debug) - common.SetLogLevelFromViper("error") return serve(args) }, } diff --git a/sampleconfig/core.yaml b/sampleconfig/core.yaml index 46ad1bbd289..12839cecb4c 100644 --- a/sampleconfig/core.yaml +++ b/sampleconfig/core.yaml @@ -30,10 +30,6 @@ logging: ledger: info msp: warning - # Error handling framework log level - when set to DEBUG, a callstack will - # be appended to all errors generated using the fabric/common/errors package - error: debug - format: '%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}' ############################################################################### @@ -204,7 +200,7 @@ peer: # establishing TLS connection rootcert: file: peer/tls.crt - + # The server name use to verify the hostname returned by TLS handshake serverhostoverride: