Recently I found some strange logs in the log, roughly like this:

Error 2020-08-28 06:59:38. 813 + 00:00... _msg=get immersion context, fetch tracks failed, error: <nil>Copy the code

Error:

Error:

Error:

Error:

= nil, but finding the corresponding line of code looks like this:



tracks, errResult = TrackService.GetRpcTracks(httpCtx, trackIds)
iferrResult ! =nil {
  logs.CtxError(httpCtx.RpcContext(), "get immersion context, fetch tracks failed, error: %v", errResult)
  return
}
Copy the code

ErrResult is of type *ErrorResult, and the GetRpcTracks function returns type *ErrorResult. After careful investigation, this possibility is ruled out.

That’s weird, errResult! = nil obviously has to be true to go down, a pointer to a non-nil structure prints out nil??

After scratching my head and failing to find an answer, I decided to look it up in the context of the log. The GetRpcTracks function retrieves Track information based on TrackIDs and returns an error if it cannot find it. Based on the log flow, find all logs for the request, one of which is displayed

Error 2020-08-28 06:59:38. 815 + 00:00... _msg=no tracks found, track ids: [676648224091215xxxx]Copy the code

The corresponding code is:

if len(tracks) == 0 {
    logs.CtxError(httpCtx.RpcContext(), "no tracks found, track ids: %v", trackIds)
    errResult = ginf_action.NewErrorResult(errors.ResourceNotFound, nil."")}Copy the code

I checked the corresponding TrackID in the database and found that the status was indeed unavailable, so the interface certainly could not check the data. In this case, the GetRpcTracks function returns the structure pointer built by ginf_action.newErrorResult (errors.resourcenotFound, nil, “”). The code for NewErrorResult is actually quite simple:

func NewErrorResult(catalog ErrorCatalog, err error, message string, params ...interface{}) *ErrorResult {
	return&ErrorResult{ Catalog: catalog, Err: err, Message: fmt.Sprintf(message, params...) ,}}Copy the code

So you can be sure, tracks, errResult = TrackService GetRpcTracks (httpCtx trackIds) return errResult really will be a problem here, so the question should be printed in the log.

So I built a new structure to test it:

type CustomNil struct {
	msg string
	err error
}

func TestErr(t *testing.T) {
	c := &CustomNil{
		msg: "",
		err: nil,
	}

	fmt.Printf("CustomNil:%v", c)
}
Copy the code

The logs are as follows:

CustomNil:&{ <nil>}
Copy the code

Error:

No & and no curly braces. So I discussed with my colleague why this happened, and he said it was probably the String method. So I added a method to CustomNil:

func (c *CustomNil) String(a) string {
	return "test"
}
Copy the code

Run again and the log looks like this:

CustomNil:test
Copy the code

Obviously, the String() method is called when the %v placeholder is used, so it’s possible that the String() method of *ErrorResult returned nil. *ErrorResult does not implement String() at all, but Error() at all, so I wonder if this guy is causing it. So I continue to experiment and add another method:

func (c *CustomNil) Error(a) string {
	return fmt.Sprint(c.err)
}
Copy the code

After re-running the code, the log looks like this:

CustomNil:<nil>
Copy the code

The %v placeholder will first call the Error() method to print the log, or the String() method if there is no Error() method. In the absence of either function, the variables in the structure will be printed sequentially.

So the question is, why is this so? So scroll down to the code:

func (l *Logger) CtxError(ctx context.Context, format string, v ...interface{}) {
	if LevelError < l.CtxLevel(ctx) {
		return
	}
	if len(v) == 0 {
		l.fmtLog(ctx, LevelError, "", format)
		return
	}
	l.fmtLog(ctx, LevelError, "", fmt.Sprintf(format, v...))
}
Copy the code

Sprintf(format, v…) in CtxError The Sprintf of the FMT package is quite complex to handle. After some research, the key code was finally found:

func (p *pp) handleMethods(verb rune) (handled bool) {
	if p.erroring {
		return}...// If we're doing Go syntax and the argument knows how to supply it, take care of it now.
	if p.fmt.sharpV {
		...
	} else {
		// If a string is acceptable according to the format, see if
		// the value satisfies one of the string-valued interfaces.
		// Println etc. set verb to %v, which is "stringable".
		switch verb {
		case 'v'.'s'.'x'.'X'.'q':
			// Is it an error or Stringer?
			// The duplication in the bodies is necessary:
			// setting handled and deferring catchPanic
			// must happen before calling the method.
			switch v := p.arg.(type) {
			case error:
				handled = true
				defer p.catchPanic(p.arg, verb, "Error")
				p.fmtString(v.Error(), verb)
				return

			case Stringer:
				handled = true
				defer p.catchPanic(p.arg, verb, "String")
				p.fmtString(v.String(), verb)
				return}}}return false
}
Copy the code

If you use the %v placeholder, you will determine whether it implements the error and Stinger interfaces and call the error () or String() methods to output.

At this point, the problem has been explored, so it’s important to keep this in mind when using the FMT package for log formatting, or you’ll end up with some weird logs that add unnecessary trouble. Of course, in this case, it is also worth discussing whether it is appropriate to record the Error level of the log.

The troubleshooting didn’t take much time, but the whole process was as enjoyable as deciphering it. It was fun, and in the end, I learned something new. I hereby record it, and hope to encourage you together.