Go語(yǔ)言之log日志

在我們開發(fā)程序后，如果有一些問題需要對(duì)程序進(jìn)行調(diào)試的時(shí)候，日志是必不可少的，這是我們分析程序問題常用的手段。

日志使用

日志分析，就是根據(jù)輸出的日志信息，分析挖掘可能的問題，我們使用fmt.Println系列函數(shù)也可以達(dá)到目的，因?yàn)樗鼈円部梢园盐覀冃枰男畔⑤敵龅浇K端或者其他文件中。不過(guò)fmt.Println系列函數(shù)輸出的系統(tǒng)比較簡(jiǎn)單，比如沒有時(shí)間，也沒有源代碼的行數(shù)等，對(duì)于我們排查問題，缺少了很多信息。

對(duì)此，Go語(yǔ)言為我們提供了標(biāo)準(zhǔn)的log包，來(lái)跟蹤日志的記錄。下面我們看看日志包log的使用。

func main() {
    log.Println("飛雪無(wú)情的博客:","http://www.flysnow.org")
    log.Printf("飛雪無(wú)情的微信公眾號(hào)：%s\\n","flysnow_org")}

使用非常簡(jiǎn)單，函數(shù)名字和用法也和fmt包很相似，但是它的輸出默認(rèn)帶了時(shí)間戳。

2017/04/29 13:18:44 飛雪無(wú)情的博客: http://www.flysnow.org
2017/04/29 13:18:44 飛雪無(wú)情的微信公眾號(hào)：flysnow_org

這樣我們很清晰的就知道了，記錄這些日志的時(shí)間，這對(duì)我們排查問題，非常有用。

有了時(shí)間了，我們還想要更多的信息，必然發(fā)生的源代碼行號(hào)等，對(duì)此日志包log為我們提供了可定制化的配制，讓我們可以自己定制日志的抬頭信息。

func init(){
    log.SetFlags(log.Ldate|log.Lshortfile)}

我們使用init函數(shù)，這個(gè)函數(shù)在main函數(shù)執(zhí)行之前就可以初始化，可以幫我們做一些配置，這里我們自定義日志的抬頭信息為時(shí)間+文件名+源代碼所在行號(hào)。也就是log.Ldate|log.Lshortfile，中間是一個(gè)位運(yùn)算符|，然后通過(guò)函數(shù)log.SetFlags進(jìn)行設(shè)置?，F(xiàn)在我們?cè)龠\(yùn)行下看看輸出的日志。

2017/04/29main.go:10: 飛雪無(wú)情的博客:http://www.flysnow.org
2017/04/29 main.go:11: 飛雪無(wú)情的微信公眾號(hào)：flysnow_org

比著上一個(gè)例子，多了源文件以及行號(hào)，但是少了時(shí)間，這就是我們自定義出來(lái)的結(jié)果?，F(xiàn)在我們看看log包為我們提供了那些可以定義的選項(xiàng)常量。

const (
    Ldate         = 1 << iota     //日期示例： 2009/01/23
    Ltime                         //時(shí)間示例: 01:23:23
    Lmicroseconds                 //毫秒示例: 01:23:23.123123.
    Llongfile                     //絕對(duì)路徑和行號(hào): /a/b/c/d.go:23
    Lshortfile                    //文件和行號(hào): d.go:23.
    LUTC                          //日期時(shí)間轉(zhuǎn)為0時(shí)區(qū)的
    LstdFlags     = Ldate | Ltime //Go提供的標(biāo)準(zhǔn)抬頭信息)

這是log包定義的一些抬頭信息，有日期、時(shí)間、毫秒時(shí)間、絕對(duì)路徑和行號(hào)、文件名和行號(hào)等，在上面都有注釋說(shuō)明，這里需要注意的是：如果設(shè)置了Lmicroseconds，那么Ltime就不生效了；設(shè)置了Lshortfile，Llongfile也不會(huì)生效，大家自己可以測(cè)試一下。

LUTC比較特殊，如果我們配置了時(shí)間標(biāo)簽，那么如果設(shè)置了LUTC的話，就會(huì)把輸出的日期時(shí)間轉(zhuǎn)為0時(shí)區(qū)的日期時(shí)間顯示。

log.SetFlags(log.Ldate|log.Ltime |log.LUTC)

那么對(duì)我們東八區(qū)的時(shí)間來(lái)說(shuō)，就會(huì)減去 8 個(gè)小時(shí)，我們看輸出：

2017/04/29 05:46:29 飛雪無(wú)情的博客: http://www.flysnow.org
2017/04/29 05:46:29 飛雪無(wú)情的微信公眾號(hào)：flysnow_org

最后一個(gè)LstdFlags表示標(biāo)準(zhǔn)的日志抬頭信息，也就是默認(rèn)的，包含日期和具體時(shí)間。

我們大部分情況下，都有很多業(yè)務(wù)，每個(gè)業(yè)務(wù)都需要記錄日志，那么有沒有辦法，能區(qū)分這些業(yè)務(wù)呢？這樣我們?cè)诓檎胰罩镜臅r(shí)候，就方便多了。

對(duì)于這種情況，Go語(yǔ)言也幫我們考慮到了，這就是設(shè)置日志的前綴，比如一個(gè)用戶中心系統(tǒng)的日志，我們可以這么設(shè)置。

func init(){

    log.SetPrefix("【UserCenter】")

    log.SetFlags(log.LstdFlags |log.Lshortfile |log.LUTC)
}

通過(guò)log.SetPrefix可以指定輸出日志的前綴，這里我們指定為【UserCenter】，然后就可以看到日志的打印輸出已經(jīng)清晰的標(biāo)記出我們的這些日志是屬于哪些業(yè)務(wù)的啦。

【UserCenter】2017/04/29 05:53:26 main.go:11: 飛雪無(wú)情的博客:http://www.flysnow.org
【UserCenter】2017/04/29 05:53:26main.go:12: 飛雪無(wú)情的微信公眾號(hào)：flysnow_org

log包除了有Print系列的函數(shù)，還有Fatal以及Panic系列的函數(shù)，其中Fatal表示程序遇到了致命的錯(cuò)誤，需要退出，這時(shí)候使用Fatal記錄日志后，然后程序退出，也就是說(shuō)Fatal相當(dāng)于先調(diào)用Print打印日志，然后再調(diào)用os.Exit(1)退出程序。

同理Panic系列的函數(shù)也一樣，表示先使用Print記錄日志，然后調(diào)用panic()函數(shù)拋出一個(gè)恐慌，這時(shí)候除非使用recover()函數(shù)，否則程序就會(huì)打印錯(cuò)誤堆棧信息，然后程序終止。

這里貼下這幾個(gè)系列函數(shù)的源代碼，更好理解。

func Println(v...interface{}) {

    std.Output(2, fmt.Sprintln(v...))
}
func Fatalln(v ...interface{}) {

    std.Output(2, fmt.Sprintln(v...))

    os.Exit(1)
}
func Panicln(v ...interface{}) {

    s := fmt.Sprintln(v...)

    std.Output(2, s)   panic(s)
}

實(shí)現(xiàn)原理

通過(guò)上面的源代碼，我們發(fā)現(xiàn)，日志包log的這些函數(shù)都是類似的，關(guān)鍵的輸出日志就在于std.Output方法。

func New(out io.Writer, prefixstring, flag int) *Logger {

    return &Logger{out: out,prefix: prefix, flag: flag}
}
var std = New(os.Stderr, "", LstdFlags)

從以上源代碼可以看出，變量std其實(shí)是一個(gè)*Logger，通過(guò)log.New函數(shù)創(chuàng)建，默認(rèn)輸出到os.Stderr設(shè)備，前綴為空，日志抬頭信息為標(biāo)準(zhǔn)抬頭LstdFlags。

os.Stderr對(duì)應(yīng)的是UNIX里的標(biāo)準(zhǔn)錯(cuò)誤警告信息的輸出設(shè)備，同時(shí)被作為默認(rèn)的日志輸出目的地。初次之外，還有標(biāo)準(zhǔn)輸出設(shè)備os.Stdout以及標(biāo)準(zhǔn)輸入設(shè)備os.Stdin。

var (
    Stdin  = NewFile(uintptr(syscall.Stdin), "/dev/stdin")
    Stdout = NewFile(uintptr(syscall.Stdout), "/dev/stdout")
    Stderr = NewFile(uintptr(syscall.Stderr), "/dev/stderr"))

以上就是定義的UNIX的標(biāo)準(zhǔn)的三種設(shè)備，分別用于輸入、輸出和警告錯(cuò)誤信息。理解了os.Stderr，現(xiàn)在我們看下Logger這個(gè)結(jié)構(gòu)體，日志的信息和操作，都是通過(guò)這個(gè)Logger操作的。

type Logger struct {

    mu     sync.Mutex //ensures atomic writes; protects the following fields

    prefix string     //prefix to write at beginning of each line

    flag   int       // properties

    out    io.Writer // destination for output

    buf    []byte    // for accumulating text to write
}

·        字段mu是一個(gè)互斥鎖，主要是是保證這個(gè)日志記錄器Logger在多goroutine下也是安全的。

·        字段prefix是每一行日志的前綴。

·        字段flag是日志抬頭信息。

·        字段out是日志輸出的目的地，默認(rèn)情況下是os.Stderr。

·        字段buf是一次日志輸出文本緩沖，最終會(huì)被寫到out里。

了解了結(jié)構(gòu)體Logger的字段，現(xiàn)在就可以看下它最重要的方法Output了，這個(gè)方法會(huì)輸出格式化好的日志信息。

func (l *Logger) Output(calldepth int, s string) error {
    now := time.Now() // get this early.
    var file string
    var line int
    //加鎖，保證多goroutine下的安全
    l.mu.Lock()
    defer l.mu.Unlock()    
    //如果配置了獲取文件和行號(hào)的話
    if l.flag&(Lshortfile|Llongfile) != 0 {        
        //因?yàn)閞untime.Caller代價(jià)比較大，先不加鎖
        l.mu.Unlock()        
        var ok bool
        _, file, line, ok = runtime.Caller(calldepth)        
        if !ok {
            file = "???"
            line = 0
        }        
        //獲取到行號(hào)等信息后，再加鎖，保證安全
        l.mu.Lock()
    }    
    //把我們的日志信息和設(shè)置的日志抬頭進(jìn)行拼接
    l.buf = l.buf[:0]
    l.formatHeader(&l.buf, now, file, line)
    l.buf = append(l.buf, s...)    
    if len(s) == 0 || s[len(s)-1] != '\\n' {
        l.buf = append(l.buf, '\\n')
    }    
    //輸出拼接好的緩沖buf里的日志信息到目的地
    _, err := l.out.Write(l.buf)    
    return err
}

整個(gè)代碼比較簡(jiǎn)潔，為了多goroutine安全互斥鎖也用上了，但是在獲取調(diào)用堆棧信息的時(shí)候，又要先解鎖，因?yàn)檫@個(gè)過(guò)程比較重。獲取到文件、行號(hào)等信息后，繼續(xù)加互斥鎖保證安全。

后面的就比較簡(jiǎn)單了，formatHeader方法主要是格式化日志抬頭信息，然后存儲(chǔ)在buf這個(gè)緩沖中，最后再把我們自己的日志信息拼接到緩沖buf的后面，然后為一次log日志輸出追加一個(gè)換行符，這樣每次日志輸出都是一行一行的。

有了最終的日志信息buf，然后把它寫到輸出的目的地out里就可以了，這是一個(gè)實(shí)現(xiàn)了io.Writer接口的類型，只要實(shí)現(xiàn)了這個(gè)接口，都可以當(dāng)作輸出目的地。

func (l *Logger) SetOutput(wio.Writer) {

    l.mu.Lock()    

    defer l.mu.Unlock()

    l.out = w
}

log包的SetOutput函數(shù)，可以設(shè)置輸出目的地。這里稍微簡(jiǎn)單介紹下runtime.Caller，它可以獲取運(yùn)行時(shí)方法的調(diào)用信息。

func Caller(skip int) (pc uintptr, file string, line int, ok bool)

參數(shù)skip表示跳過(guò)棧幀數(shù)，0 表示不跳過(guò)，也就是runtime.Caller的調(diào)用者。1 的話就是再向上一層，表示調(diào)用者的調(diào)用者。

log日志包里使用的是 2 ，也就是表示我們?cè)谠创a中調(diào)用log.Print、log.Fatal和log.Panic這些函數(shù)的調(diào)用者。

以main函數(shù)調(diào)用log.Println為例，是main->log.Println->*Logger.Output->runtime.Caller這么一個(gè)方法調(diào)用棧，所以這時(shí)候，skip的值分別代表：

·        0 表示*Logger.Output中調(diào)用runtime.Caller的源代碼文件和行號(hào)。

·        1 表示log.Println中調(diào)用*Logger.Output的源代碼文件和行號(hào)。

·        2 表示main中調(diào)用log.Println的源代碼文件和行號(hào)。

所以這也是log包里的這個(gè)skip的值為什么一直是 2 的原因。

定制自己的日志

通過(guò)上面的源碼分析，我們知道日志記錄的根本就在于一個(gè)日志記錄器Logger，所以我們定制自己的日志，其實(shí)就是創(chuàng)建不同的Logger。

var (
    Info *log.Logger
    Warning *log.Logger
    Error * log.Logger)func init(){
    errFile,err:=os.OpenFile("errors.log",os.O_CREATE|os.O_WRONLY|os.O_APPEND,0666)
    if err!=nil{
        log.Fatalln("打開日志文件失敗：",err)
    }

    Info = log.New(os.Stdout,"Info:",log.Ldate | log.Ltime | log.Lshortfile)
    Warning = log.New(os.Stdout,"Warning:",log.Ldate | log.Ltime | log.Lshortfile)
    Error = log.New(io.MultiWriter(os.Stderr,errFile),"Error:",log.Ldate | log.Ltime | log.Lshortfile)}func main() {
    Info.Println("飛雪無(wú)情的博客:","http://www.flysnow.org")
    Warning.Printf("飛雪無(wú)情的微信公眾號(hào)：%s\\n","flysnow_org")
    Error.Println("歡迎關(guān)注留言")
}

我們根據(jù)日志級(jí)別定義了三種不同的Logger，分別為Info，Warning，Error，用于不同級(jí)別日志的輸出。這三種日志記錄器都是使用log.New函數(shù)進(jìn)行創(chuàng)建。

這里創(chuàng)建Logger的時(shí)候，Info和Warning都比較正常，Error這里采用了多個(gè)目的地輸出，這里可以同時(shí)把錯(cuò)誤日志輸出到os.Stderr以及我們創(chuàng)建的errors.log文件中。

io.MultiWriter函數(shù)可以包裝多個(gè)io.Writer為一個(gè)io.Writer，這樣我們就可以達(dá)到同時(shí)對(duì)多個(gè)io.Writer輸出日志的目的。

io.MultiWriter的實(shí)現(xiàn)也很簡(jiǎn)單，定義一個(gè)類型實(shí)現(xiàn)io.Writer，然后在實(shí)現(xiàn)的Write方法里循環(huán)調(diào)用要包裝的多個(gè)Writer接口的Write方法即可。

func (t *multiWriter) Write(p []byte) (n int, err error) {
    for _, w := range t.writers {
        n, err = w.Write(p)
        if err != nil {
                    return
        } 
        if n != len(p) {
            err = ErrShortWrite            
            return
        }
    }    
    return len(p), nil
}

這里我們通過(guò)定義了多個(gè)Logger來(lái)區(qū)分不同的日志級(jí)別，使用比較麻煩，針對(duì)這種情況，可以使用第三方的log框架，也可以自定包裝定義，直接通過(guò)不同級(jí)別的方法來(lái)記錄不同級(jí)別的日志，還可以設(shè)置記錄日志的級(jí)別等。