【Go語言探險】線上奇怪日誌問題的排查
阿新 • • 發佈：2020-08-29
最近在日誌中發現一些奇怪的日誌，大致長這樣：
```shell
Error 2020-08-28 06:59:38.813+00:00 ... _msg=get immersion context, fetch tracks failed, error:
```
列印了 `Error` 日誌，`error` 打印出來卻是 ``，乍眼一看，以為又遇到了 `Go` 裡面 `nil != nil` 的問題，但找到對應的那行程式碼是這樣的：
```Go
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]
```
對應的程式碼是：
```Go
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` 的程式碼其實很簡單：
```Go
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` 確實沒什麼問題，那麼問題應該就出在列印日誌的時候了。
於是我構建了一個新的結構體來進行了測試：
```Go
type CustomNil struct {
msg string
err error
}
func TestErr(t *testing.T) {
c := &CustomNil{
msg: "",
err: nil,
}
fmt.Printf("CustomNil:%v", c)
}
```
打印出來的日誌為：
```Go
CustomNil:&{ }
```
跟之前日誌裡列印的很像，但是不一樣，前面日誌是這樣的：`error: ` 沒有 `&`，也沒有大括號。於是我跟同事討論了一下，為什麼會出現這樣的情況，同事說可能是`String`方法導致的。於是我給 `CustomNil` 加了一個方法：
```Go
func (c *CustomNil) String() string {
return "test"
}
```
重新跑一下發現日誌變成了這樣：
```Go
CustomNil:test
```
顯然，使用 `%v` 佔位符時會呼叫 `String()` 方法，所以有可能是 `*ErrorResult` 的 `String()` 方法裡返回了 `nil`。但很快發現 `*ErrorResult` 根本沒有實現 `String()` 方法，但是實現了 `Error()` 方法，便想會不會是這傢伙導致的，於是繼續進行實驗，再新增一個方法：
```Go
func (c *CustomNil) Error() string {
return fmt.Sprint(c.err)
}
```
重新跑程式碼之後，日誌長這樣：
```Go
CustomNil:
```
這下終於找到原因了，`%v` 佔位符會優先呼叫 `Error()` 方法來列印日誌，沒有 `Error()` 方法時會呼叫 `String()` 方法來列印，這兩個函式都沒有的情況下，會將結構體內的各個變數順序列印。
那麼問題來了，為什麼是這樣的呢？於是繼續往下翻程式碼：
```Go
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` 就很複雜了，經過一番研究，終於找到了關鍵程式碼：
```Go
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` 等級的日誌是否合適也是值得商討的。
這次問題排查沒有花太多時間，但整個過程就像解密一樣酣暢淋漓，感覺十分有趣，最後還能從中學到一些新東西，可謂收穫頗豐。特此記錄下來，希望能與君