最近在日誌中發現一些奇怪的日誌，大致長這樣：
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 等級的日誌是否合適也是值得商討的。
這次問題排查沒有花太多時間，但整個過程就像解密一樣酣暢淋漓，感覺十分有趣，最後還能從中學到一些新東西，可謂收穫頗豐。特此記錄下來，希望能與君共勉。