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

lppgo-github · 2020年06月17日 · 最后由 gqcn 回复于 2020年07月30日 · 612 次阅读

[TOC]

1: 问题描述

一次不小心复制使用了相同的 pattern (如下图:blackListOpt),发现程序一运行就退出,没有报错信息。最后是 pattern 重复了,但按理说,handler map 会报错,所以就在空闲时间做了分析梳理

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% 确定是异步日志

// 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() 先执行了,导致错误日志不打印**

// 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 的出现。要多学习,向各位相互学习交流**

更多原创文章干货分享,请关注公众号
  • 加微信实战群请加微信(注明:实战群):gocnio

@lppgo-github 不好意思,好久没来这个社区了,你这个问题应该是自己写日志的时候采用异步打印了

需要 登录 后方可回复, 如果你还没有账号请点击这里 注册