最近在日志中發現一些奇怪的日志，大致長這樣：
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 string
err 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 = 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
}
看到這里，就豁然開朗了，如果使用了 %v 占位符，會依次判斷它是否實現了 error 接口和 Stinger 接口並調用 Error() 或 String() 方法來進行輸出。
到此，問題就已經研究清楚了，所以使用 fmt 包來進行日志格式化時還是要注意這一點，否則就會出現一些奇奇怪怪的日志，增加不必要的麻煩。當然，在這個 case 下，這樣的情況打 Error 等級的日志是否合適也是值得商討的。
這次問題排查沒有花太多時間，但整個過程就像解密一樣酣暢淋漓，感覺十分有趣，最后還能從中學到一些新東西，可謂收獲頗豐。特此記錄下來，希望能與君共勉。