【Go语言探险】线上奇怪日志问题的排查
2020-08-29 15:11
1106 查看
最近在日志中发现一些奇怪的日志,大致长这样:
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等级的日志是否合适也是值得商讨的。
这次问题排查没有花太多时间,但整个过程就像解密一样酣畅淋漓,感觉十分有趣,最后还能从中学到一些新东西,可谓收获颇丰。特此记录下来,希望能与君共勉。
相关文章推荐
- Arthas实践--抽丝剥茧排查线上应用日志打满问题
- ELK日志系统的线上问题排查-Logstash问题
- Go语言的结构嵌入问题
- 线上性能问题初步排查方法
- 线上问题排查
- Go语言中Tcp协议粘包问题处理
- j2Cache线上异常问题排查记录
- 线上问题排查命令总结
- 排查线上问题常用的几个Linux命令
- 线上too many open files问题排查记录
- 一次CMS GC问题排查过程(理解原理+读懂GC日志)
- 利用JVM在线调试工具排查线上问题
- JVM线上问题排查过程
- Go语言:解决数据库中null值的问题
- 线上问题排查命令
- linux java 线上问题排查
- go语言常见问题
- java线上服务问题排查
- java应用线上CPU过高问题排查
- 关于Go语言中nil和interface的问题