【Go语言探险】线上奇怪日志问题的排查

【Go语言探险】线上奇怪日志问题的排查,第1张

概述最近在日志中发现一些奇怪的日志,大致长这样: Error 2020-08-28 06:59:38.813⬀:00 ... _msg=get immersion context, fetch tra

最近在日志中发现一些奇怪的日志,大致长这样:

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,error: %v",errResult)  return}

errResult 的类型是 *ErrorResultGetRpcTracks 函数返回的类型也是*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,"") 所构建的结构体指针。NewErrorResult 的代码其实很简单:

func NewErrorResult(catalog ErrorCatalog,err error,message string,params ...interface{}) *ErrorResult {	return &ErrorResult{		Catalog: catalog,Err:     err,Message: fmt.Sprintf(message,params...),}}

所以可以肯定,tracks,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() 方法,所以有可能是 *ErrorResultString() 方法里返回了 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,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,"String")				p.fmtString(v.String(),verb)				return			}		}	}	return false}

看到这里,就豁然开朗了,如果使用了 %v 占位符,会依次判断它是否实现了 error 接口和 Stinger 接口并调用 Error()String() 方法来进行输出。

到此,问题就已经研究清楚了,所以使用 fmt 包来进行日志格式化时还是要注意这一点,否则就会出现一些奇奇怪怪的日志,增加不必要的麻烦。当然,在这个 case 下,这样的情况打 Error 等级的日志是否合适也是值得商讨的。

这次问题排查没有花太多时间,但整个过程就像解密一样酣畅淋漓,感觉十分有趣,最后还能从中学到一些新东西,可谓收获颇丰。特此记录下来,希望能与君共勉。

总结

以上是内存溢出为你收集整理的【Go语言探险】线上奇怪日志问题的排查全部内容,希望文章能够帮你解决【Go语言探险】线上奇怪日志问题的排查所遇到的程序开发问题。

如果觉得内存溢出网站内容还不错,欢迎将内存溢出网站推荐给程序员好友。

欢迎分享,转载请注明来源:内存溢出

原文地址: http://outofmemory.cn/langs/1259763.html

(0)
打赏 微信扫一扫 微信扫一扫 支付宝扫一扫 支付宝扫一扫
上一篇 2022-06-07
下一篇 2022-06-07

发表评论

登录后才能评论

评论列表(0条)

保存