Beego框架的一条神秘日志引发的思考

掘金 · · 4352 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

公司目前的后台是用Beego框架搭的,并且为了服务的不中断升级,我们开启了Beego的Grace模块,用于热升级支持。一切都跑井然有序,直到有一天,领导甩出一些服务日志,告知程序一直报错:

2018/03/08 17:49:34 20848 Received SIGINT.
2018/03/08 17:49:34 20848 [::]:5490 Listener closed.
2018/03/08 17:49:34 20848 Waiting for connections to finish...
2018/03/08 17:49:34 [C] [asm_amd64.s:2337] ListenAndServe:  accept tcp [::]:5490: use of closed network connection 20848

问题出在第4行,每次服务关闭时,都会报出use of closed network connection。按理说这时候网络连接应该关闭了啊,进程都退出了,怎么还Accept 5490端口?到Beego的Issues列表里一搜,已经有人问过这个问题了(#2809),下面还没有人回答,搜也搜索不到,只剩最后一个工具了:看源码。

1. Grace模式

首先可以肯定,不开Grace模式的话,是没有这些日志打出来的,而是直接结束。因此我们先要对Beego的Grace模式有一些了解。Beego官网对此一定的介绍:Grace模块。大致是说他们参照:Grace_restart_in_golang这篇文章的思路实现的热升级功能,文章很长,讲述的思路很清晰,大体过程如下:

image

开源中国翻译-GracefulRestart 这篇中文翻译说明的更通俗易懂。明白了热升级的原理,我们就可以进入代码中详细寻找了。一切都从beego.Run()开始。

beego.Run()创建好了BeeApp对象,并且调用BeeApp.Run()执行。Run方法有不同的启动模式,在此,我们只关注Grace部分。

func (app *App) Run() {
	addr := BConfig.Listen.HTTPAddr
	...

	// run graceful mode
	if BConfig.Listen.Graceful {
		...
		if BConfig.Listen.EnableHTTP {
			go func() {
			    // 创建了GraceServer 是对http.Server的一层封装
				server := grace.NewServer(addr, app.Handlers)
				...
				if err := server.ListenAndServe(); err != nil {
					logs.Critical("ListenAndServe: ", err, fmt.Sprintf("%d", os.Getpid()))
					endRunning <- true
				}
			}()
		}
		<-endRunning
		return
	}
	...
}

代码里可以看到,logs.Critical("ListenAndServe: ", err, fmt.Sprintf("%d", os.Getpid()))正是打出上述日志的源头:

2018/03/08 17:49:34 [C] [asm_amd64.s:2337] ListenAndServe:  accept tcp [::]:5490: use of closed network connection 20848

那么为什么会返回use of closed network connection这个错误呢?跟进ListenAndServe()方法中查看:

func (srv *Server) ListenAndServe() (err error) {
    ...
    // 处理上图中的热升级信号(fork子进程),SIGINT、SIGTERM信号(进程结束信号)
	go srv.handleSignals()

    ...
    // 如果是子进程执行,Getppid()拿到父进程pid,并且Kill
	if srv.isChild {
		process, err := os.FindProcess(os.Getppid())
		if err != nil {
			log.Println(err)
			return err
		}
		err = process.Kill()
		if err != nil {
			return err
		}
	}

	log.Println(os.Getpid(), srv.Addr)
	return srv.Serve()
}

跟进Serve()方法:

func (srv *Server) Serve() (err error) {
	srv.state = StateRunning
	//这里我们传入了一个GraceListener,对net.Listener做了封装,在后面会用到。
	err = srv.Server.Serve(srv.GraceListener)
	log.Println(syscall.Getpid(), "Waiting for connections to finish...")
	//此处会等待所有连接处理完成,对应图中的父进程结束流程。
	srv.wg.Wait()
	srv.state = StateTerminate
	return
}

还是调回了http.Server.Serve()方法,看这个方法:

 func (srv *Server) Serve(l net.Listener) error {
	defer l.Close()
	...

	for {
	    //代码在这里阻塞,如果没有连接进来的话。
		rw, e := l.Accept()
		if e != nil {
			select {
			//正常的结束流程
			case <-srv.getDoneChan():
				return ErrServerClosed
			default:
			}
			...
			
			//不正常的结束流程
			return e
		}
		
		//开启一个go程处理新连接
		c := srv.newConn(rw)
		go c.serve(ctx)
	}
}

如果是正常结束,我们应该会收到ErrServerClosed,这虽然是个Error,但是类似于io.EOF,是一个正常的结束流程,问题在于,我们收到的并不是ServerClosed,而是use of closed connection,由l.Accept()方法返回,那我们进到Accept()一探究竟。

2.Accept家族

前面说了,l.Accept()l是一个GraceListener,那我们直接去看它的Accept()方法。

func (gl *graceListener) Accept() (c net.Conn, err error) {
    //调AcceptTCP()
	tc, err := gl.Listener.(*net.TCPListener).AcceptTCP()
	if err != nil {
		return
	}

    ...
    
    //每次新来一个连接+1,当连接处理完成时-1。 前面wg.Wait()等的就是这个值减为0。
	gl.server.wg.Add(1)
	return
}

还是调回了net.TCPListenerAcceptTCP(),去TCPListener下看看它的AcceptTCP()

func (l *TCPListener) AcceptTCP() (*TCPConn, error) {
	...
	c, err := l.accept()
	if err != nil {
		return nil, &OpError{Op: "accept", Net: l.fd.net, Source: nil, Addr: l.fd.laddr, Err: err}
	}
	return c, nil
}

这里我们看到返回了一个OpError,它的格式正如accept tcp [::]:5490: use of closed network connection所示,以accept开头,有netaddr信息,还有一个Err的封装,看来没有找错,错误就是从这里发出来的,赶紧进到l.accept()看看:

func (ln *TCPListener) accept() (*TCPConn, error) {
	fd, err := ln.fd.accept()
	if err != nil {
		return nil, err
	}
	//创建了新的TCP连接
	return newTCPConn(fd), nil
}

这里调了fd.accept()涉及到一点UNIX系统知识,fdfile descriptor(文件描述符),在UNIX中,一切皆文件,一个Socket连接,一个进程,都可以看作是一个个的文件,前面的图中我们介绍的热升级技术,子进程之所以能拿到父进程的Socket连接,也是父进程在fork子进程的过程中,把自己的Socket连接的文件作为启动参数传递给了子进程,从而让子进程可以通过这个文件接管新来的请求,我们直接进入ln.fd.accept()看看这个fd当中有何玄机:

func (fd *netFD) accept() (netfd *netFD, err error) {
	d, rsa, errcall, err := fd.pfd.Accept()
	if err != nil {
		if errcall != "" {
			err = wrapSyscallError(errcall, err)
		}
		//有可能
		return nil, err
	}
    
	if netfd, err = newFD(d, fd.family, fd.sotype, fd.net); err != nil {
		poll.CloseFunc(d)
		//有可能
		return nil, err
	}
	
	if err = netfd.init(); err != nil {
		fd.Close()
		//有可能
		return nil, err
	}
	...
	return netfd, nil
}

上面三处代码,都有可能返回err,通过本地运行服务,发现启动服务后,没有连接进来时,(也就是说,代码现在在Accept()阻塞,并没有走到下面的控制流程中去),这时向其发送SIGINT信号,依然会打出use of closed connection日志,这说明这个err就是由fd.pfd.Accept()方法抛出来的,进到这个方法里看看详情:

// Accept wraps the accept network call.
func (fd *FD) Accept() (int, syscall.Sockaddr, string, error) {
    ...
	if err := fd.pd.prepareRead(fd.isFile); err != nil {
		return -1, nil, "", err
	}
	for {
	    //这个accept()是对accept系统调用的封装方法
		s, rsa, errcall, err := accept(fd.Sysfd)
		...
	    switch err {
		case syscall.EAGAIN:
			if fd.pd.pollable() {
				if err = fd.pd.waitRead(fd.isFile); err == nil {
					continue
				}
			}
		...
		}
		return -1, nil, errcall, err
	}
}

函数里的accept()是对accept系统调用的封装,再往下已然超出这篇文章的范畴,那又是UNIX系统的一大篇知识,Accept家族到这结束,我们得出的结论是:这个错误是UNIX系统发出的,与我们的服务和Go语言都无关。这个结论无疑是鸵鸟式做法,尽管错误是系统发出的,但是系统不会无故的汇报错误,必然是什么操作有问题,触发系统汇报了这个错误。让我门再仔细的扫视这个方法,它首先prepareRead()准备了一番,然后才进行accept系统调用,尽管不可能是卡在这个prepareRead()方法上(因为我们的服务启动后,是可以正常接受和处理连接的),但是我们还是可以去看看这里做了哪些prepare

func (pd *pollDesc) prepareRead(isFile bool) error {
	return pd.prepare('r', isFile)
}

func (pd *pollDesc) prepare(mode int, isFile bool) error {
	if pd.runtimeCtx == 0 {
		return nil
	}
	res := runtime_pollReset(pd.runtimeCtx, mode)
	return convertErr(res, isFile)
}

最终调用了Runtimeruntime_pollReset()对IO轮询器进行重置,并且convertRuntime抛出的Err,进入这个convertErr()看看:

func convertErr(res int, isFile bool) error {
	switch res {
	case 0:
		return nil
	case 1:
		return errClosing(isFile)
	case 2:
		return ErrTimeout
	}
    ...
}

// ErrNetClosing is returned when a network descriptor is used after it has been closed. 
var ErrNetClosing = errors.New("use of closed network connection")

// Return the appropriate closing error based on isFile.
func errClosing(isFile bool) error {
	if isFile {
		return ErrFileClosing
	}
	return ErrNetClosing
}

终于,我们在不可能抛出这个Err的地方发现了这个Erruse of closed network connection。这话说的实在有些绕,因为我们知道prepareRead()是没有返回Err的,不然我们的服务也不可能启动并且监听端口,所以虽然这个地方声明了这个ErrNetClosing对象,但是却不是这里抛出来的Err。前面的分析我们已经得出结论,Err是系统返回给我们的。分析到了这里又中断了,不过我们可以拓展下思路,看看这个ErrNetClosing的注释写了什么:大意是说,当使用一个被关闭的网络描述符时,这个Error会被返回,那么我们找找这个ErrNetClosing在那里被使用到了,在prepareRead()方法附近,我们发现了下面的这个方法:

//修改了上述变量ErrNetClosing的值
var ErrNetClosing = errors.New("use of closed network connection --- 改")

func (pd *pollDesc) wait(mode int, isFile bool) error {
    ...
	res := runtime_pollWait(pd.runtimeCtx, mode)
	println("   没错,错误就是我抛出来的   res:", res)
	//如果res为1 ,抛出错误ErrNetClosing。如果res为0,err = nil。
	return convertErr(res, isFile)
}

上面的代码是我对原有代码进行修改,加上一些日志,现在重新运行,发送SIGINT信号,看看日志有什么变化:

注意:如果修改了go标准库中的代码,你需要go build -a ,添加a参数,意思是所有的代码都重新编译,这也包括go标准库中的代码。

   没错,错误就是我抛出来的    res:0
   没错,错误就是我抛出来的    res:0
2018/03/09 11:42:57 31164 0.0.0.0:5490
2018/03/09 11:43:09 31164 Received SIGINT.
2018/03/09 11:43:09 31164 [::]:5490 Listener closed.
2018/03/09 11:43:09 31164 Waiting for connections to finish...
   没错,错误就是我抛出来的    res:1
2018/03/09 11:43:09 [C] [asm_amd64.s:2337] ListenAndServe:  accept tcp [::]:5490: use of closed network connection --- 改 31164

res=0时,一切都没什么问题,当接收到SIGINT,从日志可以看到,res这时候为1,这就导致了convertErr()返回错误ErrNetClosing。看起来,这个wait()就是抛出这个错误的真正源头了。然而,我们虽然找到了它,但却没有解决我们的疑问,为什么res会被系统置为1,最终导致我们收到ErrNetClosing?到底是什么操作导致了这个错误?而且,看到这个wait()方法,不禁又有新的疑问:为什么Accept()家族最后阻塞在Accept系统调用上,错误却是这个wait()返回的,wait()Accept()家族有着怎样的关联呢?

3. 网络编程中的 AcceptWait

看来Go帮我们做了太多太多,我们只知道,服务端在ListenAndServe()中阻塞,更进一步,是在fd.Accept()方法中阻塞,等待连接的到来。而前面的分析我们却发现了一个wait()方法,无疑,wait更能比accept表达出阻塞等待的含义,我们再次审视fd.Accept()方法:

// Accept wraps the accept network call.
func (fd *FD) Accept() (int, syscall.Sockaddr, string, error) {
    ...
	if err := fd.pd.prepareRead(fd.isFile); err != nil {
		return -1, nil, "", err
	}
	for {
	    //这个accept()是对accept系统调用的封装方法,其实它是返回了的,没有阻塞
		s, rsa, errcall, err := accept(fd.Sysfd)
	    ...
	    switch err {
		case syscall.EAGAIN:
			if fd.pd.pollable() {
			    //这里调用了waitRead(),说明了上面的accept()方法其实没有阻塞,真正的阻塞在这里。
				if err = fd.pd.waitRead(fd.isFile); err == nil {
					continue
				}
			}
		}
		return -1, nil, errcall, err
	}
}

func (pd *pollDesc) waitRead(isFile bool) error {
	return pd.wait('r', isFile)
}

终于,我们发现了waitRead(),而它正是wait()方法的一层封装。形势已经清晰明了了,我们陷入了网络会阻塞在Accept()方法这个思维定势中,一直在Accept的调用链中追寻不得结果,现在来看,网络阻塞在Accept()这句话没错,但是是对应用层的代码有效,在系统底层,fd.Accept()完成会返回syscall.EAGAIN这个Err,正是捕捉到这个syscall.EAGAIN,让我们的代码停在waitRead()中,直到有连接过来。那么,wait()方法其实是对runtimeruntime_pollWait的一层封装,要知道wait()的具体内容,还要去runtime包中寻找。

//go:linkname poll_runtime_pollWait internal/poll.runtime_pollWait
func poll_runtime_pollWait(pd *pollDesc, mode int) int {
	err := netpollcheckerr(pd, int32(mode))
	if err != 0 {
		return err
	}
    ...
    //代码将会阻塞在这里,如果netpollblock()不返回true,代码将一直循环。
	for !netpollblock(pd, int32(mode), false) {
	    //循环会不断检查是否有错误,有错误则退出
		err = netpollcheckerr(pd, int32(mode))
		if err != 0 {
			return err
		}
	}
	return 0
}

func netpollcheckerr(pd *pollDesc, mode int32) int {
	if pd.closing {
	    //pd关闭会导致这里返回 1
		return 1 // errClosing
	}
	if (mode == 'r' && pd.rd < 0) || (mode == 'w' && pd.wd < 0) {
		return 2 // errTimeout
	}
	return 0
}

至此我们已经找出了res=1是出自何处,正是netpollcheckerr()返回了1,导致res接收到了1,从而抛出ErrNetClosing错误,这个错误导致我们接收到use of closed netword connection这句日志。链条到此终止,可是我们现在是只知其然,而不知其所以然。到底经历了一个怎样的过程,导致了pd.closing变成了true?这个错误又会不会影响到我们的业务逻辑,可不可以忽略?为什么同样是服务关闭,只有开启Graceful模式的服务才抛出这个错误呢?很明显要解决这些疑问,我们要调转方向,回到ListenAndServe(),找找服务是怎么被Closed的。

4. Close

func (srv *Server) ListenAndServe() (err error) {
    ...
    // 处理上图中的热升级信号(fork子进程),SIGINT、SIGTERM信号(进程结束信号)
	go srv.handleSignals()

    //如果是子进程,getListener()拿到的还是父进程的监听器,如果是父进程,创建新的监听器。
	l, err := srv.getListener(addr)
	if err != nil {
		log.Println(err)
		return err
	}

    //对监听器做包装
	srv.GraceListener = newGraceListener(l, srv)
    ...
}

func (srv *Server) handleSignals() {
	var sig os.Signal

	signal.Notify(
		srv.sigChan,
		hookableSignals...,
	)

	pid := syscall.Getpid()
	for {
		sig = <-srv.sigChan
		...
		switch sig {
		case syscall.SIGHUP:
			log.Println(pid, "Received SIGHUP. forking.")
			err := srv.fork()
			...
		case syscall.SIGINT:
			log.Println(pid, "Received SIGINT.")
			srv.shutdown()
		case syscall.SIGTERM:
			log.Println(pid, "Received SIGTERM.")
			srv.shutdown()
		...
	}
}

这里可以看到ListenAndServe()被调用时,会启动一个goroutine,等待系统信号的到来,一旦收到SIGHUP信号,则马上fork一个子进程;如果收到SIGINT或者SIGTERM信号,则会调用stv.shutdown()关闭连接,看看stv.shutdown()做了些什么:

func (srv *Server) shutdown() {
	...
	srv.state = StateShuttingDown
	if DefaultTimeout >= 0 {
		go srv.serverTimeout(DefaultTimeout)
	}
	err := srv.GraceListener.Close()
	...
}

func (srv *Server) serverTimeout(d time.Duration) {
	...
	time.Sleep(d)
	//当d时间过去后,进程结束休眠,强制将计数器置0
	for {
		if srv.state == StateTerminate {
			break
		}
		//计数器减1
		srv.wg.Done()
	}
}

这里调用了GraceListenerClose(),前面我们说过,这个GraceListener实际上是对TCPListener的封装。主要是在Accept()中添加一个计数器,当有连接来了,计数器加1,连接处理完成,计数器减1。当然,如果网络有延迟,或者客户端有连接被挂起导致计数器不为0,经过DefaultTimeout(60秒)后,serverTimeout()会强制把计数器置为0。那么,我们进入Close()方法看看如何关闭监听。

func (gl *graceListener) Close() error {
	if gl.stopped {
		return syscall.EINVAL
	}
	//简单的向stop channer 发送nil信号
	gl.stop <- nil
	//等待TCPListener.Close()执行完毕
	return <-gl.stop
}

func newGraceListener(l net.Listener, srv *Server) (el *graceListener) {
	el = &graceListener{
		Listener: l,
		stop:     make(chan error),
		server:   srv,
	}
	//开启一个goroutine,不阻塞代码
	go func() {
	    //等待Close()的nil信号
		<-el.stop
		el.stopped = true
		el.stop <- el.Listener.Close()
	}()
	return
}

这里涉及到goroutine间的通信,在我们新建这个GraceListener时,就已经在监听结束信号了,代码将在<-el.stop阻塞,直到gl.stop<-nil语句被执行,stoped被置为true,且调用TCPListener.Close()并等待其执行完毕。那么TCPListener.Close()又执行了什么操作?

func (l *TCPListener) Close() error {
	...
	if err := l.close(); err != nil {
		return &OpError{Op: "close", Net: l.fd.net, Source: nil, Addr: l.fd.laddr, Err: err}
	}
	return nil
}

func (ln *TCPListener) close() error {
	return ln.fd.Close()
}

Close()方法是对close()方法的封装,因为Go中没有访问修饰符,方法首字母的大小写就代表这个方法是公有的还是私有的。所以Close()-close()也算是Go的特色了。close()方法调用了fd.close(),前面我们分析过了,这个fd是指文件描述符,也就是当前的Socket连接,这个连接被关闭,我们就不能接受新连接了。

func (fd *netFD) Close() error {
	runtime.SetFinalizer(fd, nil)
	return fd.pfd.Close()
}

func (fd *FD) Close() error {
	...
	fd.pd.evict()
	return fd.decref()
}

func (pd *pollDesc) evict() {
	if pd.runtimeCtx == 0 {
		return
	}
	runtime_pollUnblock(pd.runtimeCtx)
}

最终还是调用了runtime_pollUnblock(),直接看runtime包的源码:

func poll_runtime_pollUnblock(pd *pollDesc) {
	lock(&pd.lock)
	if pd.closing {
		throw("runtime: unblock on closing polldesc")
	}
	pd.closing = true
	...
}

还记得我们分析Wait过程说的pd.closing,正是它为true导致了res=1:

     //如果netpollblock()不返回true,代码将一直循环
	for !netpollblock(pd, int32(mode), false) {
	    //循环会不断检查是否有错误,有错误则退出
		err = netpollcheckerr(pd, int32(mode))
	    ...
	}
	---------
	if pd.closing {
	    //pd关闭会导致这里返回 1
		return 1 // errClosing
	}

现在可以清晰的了解到发生了什么了,上面的代码吧pd.closing置为true,而Accpet()所在的goroutine检查到这个值发生了改变,于是终止了Accept()过程并报错,这些goroutine的关系如下图所示:

goroutine分析

上图中的三个goroutine,从最右边的shutdown()开始看起,一步一步的完成关闭流程。最左边的是Accept()所在的goroutine一般我们正常结束程序的话,这个goroutine会正常返回。但是我们为了实现Graceful模式,还新建了两个goroutine,正是这两个新建的goroutine合作把当前的网络连接关闭,Accept()所在的goroutine不了解当前状况,以为是意外的关闭,导致我们收到那行Err日志。但是,这种关闭并不会对现有程序有什么影响,因为是我们知道是自己主动执行的这个过程。

5. 后记

       Beego日志的分析过程算是结束了,文章很长,能看到最后的小伙伴都是棒棒的,虽然我中途考虑过分成两篇,权衡之下还是作罢,因为这些分析前后相连,也是我思路的文字记录,如果分开,总是有被强行打断之感,想必读者也会觉得麻烦,不如一气呵成,刨根问底来的痛快。为了照顾读者,以及用手机阅读的人,此文引用的代码尽量精简,并且在该注释的地方做了注释,望能在这信息爆炸的时代,读者(也包括未来的我)能尽快的从中提取出关键信息来。
       在我预计要写这篇文章时,远没有现在这么长,不过是发现了Accept阻塞时,fd.close()以后系统会报'use of network connection'错误,但不影响业务逻辑。但是随着文章的推进,一个又一个问题不断冒出来,促使我更深入的去寻找答案,也算是一个意外的学习过程。也使我最近一直在考虑,追溯一个问题的答案,到底要到何种地步?在编程技术被高度封装的今天,我们要窥探到语言底层为止?还是操作系统层面?亦或者深入到汇编,对每个寄存器,每条指令都有所涉猎?前人和我们把计算机这座山越堆越高,我们站在高处,是否有一天会望不到山下的景象了,也许穷尽一生也学不尽最底下的东西。最近还听说JS现在被各种封装,甚至很多语言都是先编译成JS再运行,有人说JS都快成前端的汇编了。又听说了Flutter,这个框架封装了Android和iOS的开发流程,提供更高层次的接口兼容两个平台的开发。不禁有些迷茫,新潮的技术层出不穷,去年RN、Weex还火的不行,今年就出了跨平台开发的大杀器,年年翻新,还学的过来么?
       这次的分析过程倒是对这些问题有了一点心得,文中对Accept过程分析到Accept系统调用就没再往下了,在对wait函数的分析中,分析到了runtime也就停止了,至于那些系统内核的事儿,一概没有涉及(也不懂)。因为这些现有的分析,足以形成对文章开头那个问题的解释,并且得出不会影响现有业务流程的结论。毕竟你的领导,他想要的只有结果。如果你先有的知识能hold住你的工作,那就没必要做无谓的涉猎。毕竟学以致用,最终还是为了那份薪水服务。如果想要更好的薪水,找到更好的工作,导致能力上hold不住,那自然而然会去主动补充自己。毕竟人生苦短,我用Python少加班,多干干自己喜欢的事,多陪陪重要的人。

6. 参考文献

Golang网络:核心API实现剖析

epoll 或者 kqueue 的原理是什么?

直接修改go语言包中的源码,编译程序,修改是否生效?

Graceful Restart in Golang

Socket层实现系列 — accept()的实现


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

本文来自:掘金

感谢作者:掘金

查看原文:Beego框架的一条神秘日志引发的思考

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

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