Questions and suggestions for handling error logs

[dc7303]

Question:
Are there any standards currently suggesting when to print (or resolve) the error log?

The reason I am asking this question is that when I check the current error handling code, there is a possibility that some mistakes can occur, and I thought that it might also cause confusion for developers who are starting Yorkie.

Let's take a few examples.

1. Duplicate log output
   example:
   locker and When to use lockers
   watchDocs() and When to use watchDocs()

2. Errors that are not output to the log.
   example:
   The ObjectToBytes function does not log output to the to JSONElement(obj) method, so if the caller does not output the error, the corresponding error is not logged.
   Also, if the caller leaves a log, the error log for proto.Marshal(pbElem) may be duplicated.

3. The hassle of checking whether the log is output along the call stack to determine when to output the log.
   For example, in the case of PushPull(), a code that outputs an error and a code that does not return an error are mixed.

I think would be nice to document how the error log is handled to prevent mistakes like this.
If there is no standard, I would like to suggest 'Only handle errors once' section of 'Don't just check errors, handle them gracefully' aticle.

Suggestion:
How about making the error log output when the error chain is broken (the first caller, the time of panic, etc.) by referring to the attached article?

[hackerwins]

Currently, we are wrapping error contexts using fmt.Errorf introduced in Go 1.13. We can add simple context information using fmt.Errorf, but we cannot add stacktrace.

It would also be good to consider adding stacktrace to err using github.com/pkg/errors.Errorf and print log from top level caller.

https://stackoverflow.com/questions/61933650/whats-the-difference-between-errors-wrapf-errors-errorf-and-fmt-errorf

[dc7303]

@hackerwins
There was a problem with pkg/errors printing duplicate stack traces. This problem is more steps to wrap the error, the more verbose the stack trace becomes and the worse the readability becomes.

However, it is currently difficult to efficiently trace the stack with only the uber-go/zap logger.

In the end, I had no choice but to find a library that could trace the stack trace and found https://github.com/rotisserie/eris.
It would be good to read this.

rotisserie/eris can be used with zap as in the example below.

And by using golangci-lint, it seems that the convention for error and log handling can be checked at the CI stage to some extent.

Example

package main

import (
	"fmt"

	"github.com/rotisserie/eris"
	"go.uber.org/zap"
)

var (
	ErrInternalServer = eris.New("error internal server")
)

func main() {
	logger, _ := zap.NewProduction()
	defer logger.Sugar()

	err := fn()
	logger.Error("failed ", zap.Error(err))
	fmt.Println("----------------------")
	fmt.Printf("%+v", err)
}

func fn() error {
	return fn1()
}

func fn1() error {
	return fn2()
}

func fn2() error {
	err := eris.Wrapf(ErrInternalServer, "step 1")
	err = eris.Wrapf(err, "step 2")
	return eris.Wrapf(err, "step 3")
}

OUTPUT

{"level":"error","ts":1663294986.3542552,"caller":"eris_test/main.go:19","msg":"failed ","error":"step 3: step 2: step 1: error internal server","errorVerbose":"step 3\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:35\nstep 2\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:34\nstep 1\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:33\nerror internal server\n\tmain.main:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:18\n\tmain.fn:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:25\n\tmain.fn1:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:29\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:35\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:34\n\tmain.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:33","stacktrace":"main.main\n\t/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:19\nruntime.main\n\t/opt/homebrew/Cellar/go/1.19.1/libexec/src/runtime/proc.go:250"}
----------------------
step 3
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:35
step 2
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:34
step 1
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:33
error internal server
        main.main:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:18
        main.fn:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:25
        main.fn1:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:29
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:35
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:34
        main.fn2:/Users/choedongcheol/Workspace/dc7303/eris_test/main.go:33%  

[hackerwins]

Thanks for the research. We applied some improvements during this issue. We haven't perfected the stack output issue yet, but I'll close this PR for now.