爱站程序员基地最近在日志中发现一些奇怪的日志，大致长这样：
Error 2020-08-28 06:59:38.813+00:00 ... _msg=get immersion context, fetch tracks failed, error: <nil>
打印了
Error
日志，
error
打印出来却是
<nil>
，乍眼一看，以为又遇到了
Go
里面
nil != nil
的问题，但找到对应的那行代码是这样的：
tracks, errResult = TrackService.GetRpcTracks(httpCtx, trackIds)if errResult != nil {logs.CtxError(httpCtx.RpcContext(), "get immersion context, fetch tracks failed, error: %v", errResult)return}
errResult
的类型是
*ErrorResult
，
GetRpcTracks
函数返回的类型也是
*ErrorResult
，经过仔细研究，排除了这种可能性。
那就很奇怪了，
errResult != nil
显然要成立才会往下走，一个非
nil
的结构体指针打印出来却是
nil
？？？
就在挠头搔耳也找不到答案时，决定再根据日志上下文来查找答案。
GetRpcTracks
函数是根据
TrackIDs
来获取
Track
信息，如果找不到会返回错误。根据日志流，找到该请求的全部日志，其中有一条显示
Error 2020-08-28 06:59:38.815+00:00 ... _msg=no tracks found, track ids: [676648224091215xxxx]
对应的代码是：
if len(tracks) == 0 {logs.CtxError(httpCtx.RpcContext(), "no tracks found, track ids: %v", trackIds)errResult = ginf_action.NewErrorResult(errors.ResourceNotFound, nil, "")}
上数据库里查了一下对应的TrackID，发现状态确实为不可用，所以接口肯定查不出来数据，这样的话
GetRpcTracks
函数返回的就是由
ginf_action.NewErrorResult(errors.ResourceNotFound, nil, "")
所构建的结构体指针。
NewErrorResult
的代码其实很简单：
func NewErrorResult(catalog ErrorCatalog, err error, message string, params ...interface{}) *ErrorResult {return &ErrorResult{Catalog: catalog,Err: err,Message: fmt.Sprintf(message, params...),}}
所以可以肯定，
tracks, errResult = TrackService.GetRpcTracks(httpCtx, trackIds)
这里返回的
errResult
确实没什么问题，那么问题应该就出在打印日志的时候了。
于是我构建了一个新的结构体来进行了测试：
type CustomNil struct {msg stringerr error}func TestErr(t *testing.T) {c := &CustomNil{msg: "",err: nil,}fmt.Printf("CustomNil:%v", c)}
打印出来的日志为：
CustomNil:&{ <nil>}
跟之前日志里打印的很像，但是不一样，前面日志是这样的：
error: <nil>
没有
&
，也没有大括号。于是我跟同事讨论了一下，为什么会出现这样的情况，同事说可能是
String
方法导致的。于是我给
CustomNil
加了一个方法：
func (c *CustomNil) String() string {return "test"}
重新跑一下发现日志变成了这样：
CustomNil:test
显然，使用
%v
占位符时会调用
String()
方法，所以有可能是
*ErrorResult
的
String()
方法里返回了
nil
。但很快发现
*ErrorResult
根本没有实现
String()
方法，但是实现了
Error()
方法，便想会不会是这家伙导致的，于是继续进行实验，再添加一个方法：
func (c *CustomNil) Error() string {return fmt.Sprint(c.err)}
重新跑代码之后，日志长这样：
CustomNil:<nil>
这下终于找到原因了，
%v
占位符会优先调用
Error()
方法来打印日志，没有
Error()
方法时会调用
String()
方法来打印，这两个函数都没有的情况下，会将结构体内的各个变量顺序打印。
那么问题来了，为什么是这样的呢？于是继续往下翻代码：
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...))}
CtxError
方法里调用了
fmt.Sprintf(format, v...)
来处理参数，
fmt
包的
Sprintf
就很复杂了，经过一番研究，终于找到了关键代码：
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 = truedefer p.catchPanic(p.arg, verb, "Error")p.fmtString(v.Error(), verb)returncase Stringer:handled = truedefer p.catchPanic(p.arg, verb, "String")p.fmtString(v.String(), verb)return}}}return false}
看到这里，就豁然开朗了，如果使用了
%v
占位符，会依次判断它是否实现了
error
接口和
Stinger
接口并调用
Error()
或
String()
方法来进行输出。
到此，问题就已经研究清楚了，所以使用
fmt
包来进行日志格式化时还是要注意这一点，否则就会出现一些奇奇怪怪的日志，增加不必要的麻烦。当然，在这个
case
下，这样的情况打
Error
等级的日志是否合适也是值得商讨的。
这次问题排查没有花太多时间，但整个过程就像解密一样酣畅淋漓，感觉十分有趣，最后还能从中学到一些新东西，可谓收获颇丰。特此记录下来，希望能与君共勉。
