goframe框架 一个简单bug,排查过程分享

18393910396 · · 3233 次点击 · 开始浏览    置顶
这是一个创建于 的主题,其中的信息可能已经有所发展或是发生改变。

[TOC] # 1: 问题描述 **一次不小心复制使用了相同的pattern (如下图:blackListOpt),发现程序一运行就退出,没有报错信息。最后是pattern重复了,但按理说,handler map会报错,所以就在空闲时间做了分析梳理** ```go s.Use(MiddlewareCORS, JWTAuth) user := new(api.AccountController) s.BindHandler("POST:/user/login", user.Login) s.BindHandler("GET:/user/userInfo", user.GetUserInfo) s.BindHandler("POST:/user/blackListOpt", user.BlackListOpt) s.BindHandler("POST:/user/blackListOpt", user.Report) ``` # 2: 先看handler注册 **发现setHandler方法里面有重复路由检测,并会进行log.Fatal** ** 思考:为什么glog.fatal没有输出打印信息呢? ** ** 猜测: 没有来得及打印日志就退出了。极大可能是异步日志。** ** 验证: 添加fmt.Println,发现可以正常打印,在源码设置sleep之后也可以正常输出,基本上100%确定是异步日志** ```go // handler会注册到这个切片中 var ( preBindItems = make([]preBindItem, 0, 64) ) // handler注册具体实现 func (g *RouterGroup) preBind(bindType string, pattern string, object interface{}, params ...interface{}) *RouterGroup { preBindItems = append(preBindItems, preBindItem{ group: g, bindType: bindType, pattern: pattern, object: object, params: params, }) return g } // 在server.Start()中,会遍历preBindItems ,并作检测 func (s *Server) handlePreBindItems() { for k, item := range preBindItems { // Handle the items of current server. if item.group.server != nil && item.group.server != s { continue } if item.group.domain != nil && item.group.domain.s != s { continue } item.group.doBind(item.bindType, item.pattern, item.object, item.params...) } } // --------------注意-------------- 路由注册处理方法。 // 非叶节点为哈希表检索节点,按照URI注册的层级进行高效检索,直至到叶子链表节点; // 叶子节点是链表,按照优先级进行排序,优先级高的排前面,按照遍历检索,按照哈希表层级检索后的叶子链表数据量不会很大,所以效率比较高; // 发现框架有处理--注册地址记录及重复注册判断 func (s *Server) setHandler(pattern string, handler *handlerItem) { handler.itemId = handlerIdGenerator.Add(1) domain, method, uri, err := s.parsePattern(pattern) if err != nil { glog.Fatal("invalid pattern:", pattern, err) return } if len(uri) == 0 || uri[0] != '/' { glog.Fatal("invalid pattern:", pattern, "URI should lead with '/'") return } // 注册地址记录及重复注册判断 regKey := s.handlerKey(handler.hookName, method, uri, domain) if !s.config.RouteOverWrite { switch handler.itemType { case gHANDLER_TYPE_HANDLER, gHANDLER_TYPE_OBJECT, gHANDLER_TYPE_CONTROLLER: if item, ok := s.routesMap[regKey]; ok { fmt.Printf(`1 duplicated route registry "%s", already registered at %s`, pattern, item[0].file) glog.Fatalf(`2 duplicated route registry "%s", already registered at %s`, pattern, item[0].file) return } } } ``` # 3: 继续深入源码glog.Fatalf() ** 终于找见了,把printToWriter放到grpool ,异步执行。os.Exit()先执行了,导致错误日志不打印** ```go // glog.Fatalf方法 func (l *Logger) Fatalf(format string, v ...interface{}) { l.printErr("[FATA]", l.format(format, v...)) //time.Sleep(time.Second*1) os.Exit(1) } //printErr 方法 func (l *Logger) printErr(lead string, value ...interface{}) { if l.config.StStatus == 1 { if s := l.GetStack(); s != "" { value = append(value, "\nStack:\n"+s) } } // In matter of sequence, do not use stderr here, but use the same stdout. l.print(os.Stdout, lead, value...) } //print方法 // 发现了关键字ASYNC, 哈哈,离真相越来越近了 if l.config.Flags&F_ASYNC > 0 { err := asyncPool.Add(func() { l.printToWriter(std, buffer) }) if err != nil { intlog.Error(err) } } else { l.printToWriter(std, buffer) } // 这难道就是真相? F_ASYNC = 1 << iota // Print logging content asynchronously。 日志异步打印 // 是的,把printToWriter放到grpool ,异步执行 // Add pushes a new job to the pool. // The job will be executed asynchronously. func (p *Pool) Add(f func()) error { for p.closed.Val() { return errors.New("pool closed") } p.list.PushFront(f) // Check whether fork new goroutine or not. var n int for { n = p.count.Val() if p.limit != -1 && n >= p.limit { // No need fork new goroutine. return nil } if p.count.Cas(n, n+1) { // Use CAS to guarantee atomicity. break } } p.fork() return nil } ``` # 4:反思 ** 还是写代码要多细心,尽量减少低级 Bug 的出现。要多学习,向各位相互学习交流**

有疑问加站长微信联系(非本文作者)

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

3233 次点击  ∙  1 赞  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传