【workaround】go语言中用log4go输出信息时有bug:只输出部分信息,甚至是无任何输出

【问题】

折腾:

【记录】go语言中处理http的cookie

中的:

【已解决】go语言中的字符串数组

的时候,遇到一个很诡异的问题:

log4go输出到console的信息不全,

而对应的输出到log文件中的信息是全的。

此处的一些背景是:

之前通过:

【已解决】go语言中实现log信息同时输出到文件和控制台(命令行)

中的:

【记录】go语言中通过log4go实现同时输出log信息到log文件和console

已经是可以正常,即全部的log的信息,包括后续得到的cookie的各种信息,一共3个cookie,和后续的信息,

都是可以正常的输出到console和log文件中的。

然后此处经过了一段时间的调试,即,先后运行了很多次。

 

【折腾过程】

1.开始以为是log4go的那个rotate导致的呢,但是发现自己的代码中,已经是对于log文件的话,没用rotate:

gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))

2.然后又以为是返回的cookie值的某个域,是nil,然后可能会导致log打印输出为空呢。

但是通过注释掉对应的行,结果还是输出信息不全。

3.经过多次尝试,发现同样的代码的前提下,多次运行,每次输出截止到的地方都不同。

4.后来又经过一番调试,最后发现:

现象是:

虽然代码都是正常的:

/*
 * [File]
 * EmulateLoginBaidu.go
 * 
 * [Function]
 * 【记录】用go语言实现模拟登陆百度
 * http://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * http://www.crifan.com/about/me/
 */
package main

import (
    "fmt"
    //"builtin"
    //"log"
    "os"
    "runtime"
    "path"
    "strings"
    //"io"
    "time"
    "io/ioutil"
    "net/http"
    //"net/http/cookiejar"
    //"sync"
    //"net/url"
)

//import l4g "log4go.googlecode.com/hg"
//import l4g "code.google.com/p/log4go"
import "code.google.com/p/log4go"

/***************************************************************************************************
    Global Variables
***************************************************************************************************/
var gCurCookies []*http.Cookie;
//var gLogger *log.Logger;
var gLogger log4go.Logger;

/***************************************************************************************************
    Functions
***************************************************************************************************/
//do init before all others
func initAll(){
    gCurCookies = nil
    gLogger = nil
    
    initLogger()
    initCrifanLib()
}

//de-init for all
func deinitAll(){
    gCurCookies = nil
    if(nil == gLogger) {
        //gLogger.Close();
        gLogger = nil
    }
}

//do some init for crifanLib
func initCrifanLib(){
    gLogger.Debug("init for crifanLib")
    gCurCookies = nil
    return
}

//init for logger
func initLogger(){
    var filenameOnly string
    filenameOnly = GetCurFilename()
    var logFilename string =  filenameOnly + ".log";
    
    //gLogger = log4go.NewLogger()
    //gLogger = make(log4go.Logger)
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    
    gLogger = log4go.NewDefaultLogger(log4go.INFO)
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))

    return
}

// GetCurFilename
// Get current file name, without suffix
func GetCurFilename() string {
    _, fulleFilename, _, _ := runtime.Caller(0)
    //fmt.Println(fulleFilename)
    var filenameWithSuffix string
    filenameWithSuffix = path.Base(fulleFilename)
    //fmt.Println("filenameWithSuffix=", filenameWithSuffix)
    var fileSuffix string
    fileSuffix = path.Ext(filenameWithSuffix)
    //fmt.Println("fileSuffix=", fileSuffix)
    
    var filenameOnly string
    filenameOnly = strings.TrimSuffix(filenameWithSuffix, fileSuffix)
    //fmt.Println("filenameOnly=", filenameOnly)
    
    return filenameOnly
}

//get url response html
func GetUrlRespHtml(url string) string{
    gLogger.Info("GetUrlRespHtml, url=%s", url)
    
    var respHtml string = "";
    
    resp, err := http.Get(url)
    gLogger.Info("http.Get done")
    gLogger.Info("resp.Header=%s", resp.Header)
    gLogger.Info("resp.Status=%s", resp.Status)
    if err != nil {
        gLogger.Warn("http get url=%s response error=%s\n", url, err.Error())
    }

    // defer resp.Body.Close()
    // gLogger.Info("defer resp.Body.Close done")
    
    body, errReadAll := ioutil.ReadAll(resp.Body)
    fmt.Println("ioutil.ReadAll done")
    resp.Body.Close()
    fmt.Println("resp.Body.Close done")
    gLogger.Info("ioutil.ReadAll done")
    fmt.Println("gLogger.Info done")
    if errReadAll != nil {
        gLogger.Warn("ioutil.ReadAll for url=%s got error=%s\n", url, errReadAll.Error())
    }
    //gLogger.Debug("body=%s\n", body)

    gCurCookies = resp.Cookies()
    gLogger.Info("resp.Cookies done")
    fmt.Println("resp.Cookies done")
    
    respHtml = string(body)
    gLogger.Info("resp body []byte to string done")
    //respHtml = "just for test log ok or not"

    return respHtml
}

func printCurCookies() {
    var cookieNum int = len(gCurCookies);
    gLogger.Info("cookieNum=%d", cookieNum)
    for i := 0; i < cookieNum; i++ {
        var curCk *http.Cookie = gCurCookies[i];
        //gLogger.Info("curCk.Raw=%s", curCk.Raw)
        gLogger.Info("------ Cookie [%d]------", i)
        gLogger.Info("Name\t=%s", curCk.Name)
        gLogger.Info("Value\t=%s", curCk.Value)
        gLogger.Info("Path\t=%s", curCk.Path)
        gLogger.Info("Domain\t=%s", curCk.Domain)
        gLogger.Info("Expires\t=%s", curCk.Expires)
        gLogger.Info("RawExpires=%s", curCk.RawExpires)
        gLogger.Info("MaxAge\t=%d", curCk.MaxAge)
        gLogger.Info("Secure\t=%t", curCk.Secure)
        gLogger.Info("HttpOnly=%t", curCk.HttpOnly)
        gLogger.Info("Raw\t=%s", curCk.Raw)
        gLogger.Info("Unparsed=%s", curCk.Unparsed)
    }
}

func main() {
    initAll()

    gLogger.Info("this is EmulateLoginBaidu.go")

    //step1: access baidu url to get cookie BAIDUID
    var baiduMainUrl string
    baiduMainUrl = "http://www.baidu.com/";
    //baiduMainUrl := "http://www.baidu.com/";
    //var baiduMainUrl string = "http://www.baidu.com/";
    gLogger.Info("baiduMainUrl=%s", baiduMainUrl)
    respHtml := GetUrlRespHtml(baiduMainUrl)
    log4go.Debug("respHtml=%s", respHtml)
    //gLogger.Debug("respHtml=%s", respHtml)
    //printCurCookies()
    
    //gLogger.Error("why log can not show ????????")
    
    //var cookieNameListToCheck []string = ["BAIDUID"]
    //toCheckCookieNameList := [1]string{"BAIDUID"}
    toCheckCookieNameList := []string{"BAIDUID"}
    toCheckCookieNum := len(toCheckCookieNameList)
    gLogger.Info("toCheckCookieNum=%d\n", toCheckCookieNum) //toCheckCookieNum=1
    //fmt.Printf("toCheckCookieNum=%d\n", toCheckCookieNum) //toCheckCookieNum=1
    for i := 0; i < toCheckCookieNum; i++ {
        cookieName := toCheckCookieNameList[i];
        gLogger.Info("[%d]cookieName=%s", i, cookieName)
        //fmt.Printf("[%d]cookieName=%s\n", i, cookieName) //[0]cookieName=BAIDUID
    }
    
    deinitAll()
}

但是最终,只能输出到

resp.Cookies done

这一步,而后面的所有的信息,不论是info还是debug,不论是输出到console还是log文件,都是没了:

console only show until resp cookies

log file only show until resp status

所以,很是奇怪。

至少,看起来,是log4go的bug。

无法正常输出log信息。

6.开始以为是:

body, errReadAll := ioutil.ReadAll(resp.Body)

的问题呢,结果上面代码证明了,也不是没有死在ReadAll,程序是可以正常运行下去的。

只是log4go有问题,无法输出而已。

7.所以,实在不行的话,搞得只能去重新使用旧的方法:

【记录】go语言中通过io的MultiWriter实现同时输出log信息到log文件和console

去实现输出log了。。。

虽然该法有缺点,但是估计应该会很稳定。

8.再继续去试试,看看能否找到根本原因,

到底是不是log4go的bug,还是其他问题。

9。也是看到了log4go中的:

func (ConsoleLogWriter) LogWrite
func (w ConsoleLogWriter) LogWrite(rec *LogRecord)

This is the ConsoleLogWriter’s output method. This will block if the output buffer is full.

感觉,或许真的是当前此处的log4go,内部是什么buffer满了。而导致无法继续输出了。

但是还是无法确定。

10.去试试,换个log文件,看看能否正常输出:

    //var logFilename string =  filenameOnly + ".log";
    var logFilename string =  "log4go_debug_1.log";

看看结果如何,结果问题依旧,看来和log文件无关。

11.而且,之前也遇到这样的诡异事情。

对于如下代码,是把抓取网页的部分,都注释掉了:

/*
 * [File]
 * EmulateLoginBaidu.go
 * 
 * [Function]
 * 【记录】用go语言实现模拟登陆百度
 * http://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * http://www.crifan.com/about/me/
 */
package main

import (
    //"fmt"
    //"builtin"
    //"log"
    "os"
    "runtime"
    "path"
    "strings"
    //"io"
    "time"
    //"io/ioutil"
    "net/http"
    //"net/http/cookiejar"
    //"sync"
    //"net/url"
)

//import l4g "log4go.googlecode.com/hg"
//import l4g "code.google.com/p/log4go"
import "code.google.com/p/log4go"

/***************************************************************************************************
    Global Variables
***************************************************************************************************/
var gCurCookies []*http.Cookie;
//var gLogger *log.Logger;
var gLogger log4go.Logger;

/***************************************************************************************************
    Functions
***************************************************************************************************/
//do init before all others
func initAll(){
    gCurCookies = nil
    gLogger = nil
    
    initLogger()
    initCrifanLib()
}

//de-init for all
func deinitAll(){
    gCurCookies = nil
    if(nil == gLogger) {
        //gLogger.Close();
        gLogger = nil
    }
}

//do some init for crifanLib
func initCrifanLib(){
    gLogger.Debug("init for crifanLib")
    gCurCookies = nil
    return
}

//init for logger
func initLogger(){
    //var filenameOnly string
    //filenameOnly = GetCurFilename()
    //var logFilename string =  filenameOnly + ".log";
    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    //gLogger = make(log4go.Logger)
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    
    gLogger = log4go.NewDefaultLogger(log4go.INFO)
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))

    return
}

// GetCurFilename
// Get current file name, without suffix
func GetCurFilename() string {
    _, fulleFilename, _, _ := runtime.Caller(0)
    //fmt.Println(fulleFilename)
    var filenameWithSuffix string
    filenameWithSuffix = path.Base(fulleFilename)
    //fmt.Println("filenameWithSuffix=", filenameWithSuffix)
    var fileSuffix string
    fileSuffix = path.Ext(filenameWithSuffix)
    //fmt.Println("fileSuffix=", fileSuffix)
    
    var filenameOnly string
    filenameOnly = strings.TrimSuffix(filenameWithSuffix, fileSuffix)
    //fmt.Println("filenameOnly=", filenameOnly)
    
    return filenameOnly
}

//get url response html
func GetUrlRespHtml(url string) string{
    gLogger.Info("GetUrlRespHtml, url=%s", url)
    
    var respHtml string = "";
    
    // resp, err := http.Get(url)
    // gLogger.Info("http.Get done")
    // gLogger.Info("resp.Header=%s", resp.Header)
    // gLogger.Info("resp.Status=%s", resp.Status)
    // if err != nil {
        // gLogger.Warn("http get url=%s response error=%s\n", url, err.Error())
    // }

    // // defer resp.Body.Close()
    // // gLogger.Info("defer resp.Body.Close done")
    
    // //body, errReadAll := ioutil.ReadAll(resp.Body)
    // //body, _ := ioutil.ReadAll(resp.Body)
    // fmt.Println("ioutil.ReadAll done")
    // resp.Body.Close()
    // fmt.Println("resp.Body.Close done")
    // gLogger.Info("ioutil.ReadAll done")
    // fmt.Println("gLogger.Info done")
    // // if errReadAll != nil {
        // // gLogger.Warn("ioutil.ReadAll for url=%s got error=%s\n", url, errReadAll.Error())
    // // }
    // //gLogger.Debug("body=%s\n", body)

    // gCurCookies = resp.Cookies()
    // gLogger.Info("resp.Cookies done")
    // fmt.Println("resp.Cookies done")
    
    respHtml = "just for test log ok or not"
    //respHtml = string(body)
    gLogger.Info("resp body []byte to string done")
    

    return respHtml
}

func printCurCookies() {
    var cookieNum int = len(gCurCookies);
    gLogger.Info("cookieNum=%d", cookieNum)
    for i := 0; i < cookieNum; i++ {
        var curCk *http.Cookie = gCurCookies[i];
        //gLogger.Info("curCk.Raw=%s", curCk.Raw)
        gLogger.Info("------ Cookie [%d]------", i)
        gLogger.Info("Name\t=%s", curCk.Name)
        gLogger.Info("Value\t=%s", curCk.Value)
        gLogger.Info("Path\t=%s", curCk.Path)
        gLogger.Info("Domain\t=%s", curCk.Domain)
        gLogger.Info("Expires\t=%s", curCk.Expires)
        gLogger.Info("RawExpires=%s", curCk.RawExpires)
        gLogger.Info("MaxAge\t=%d", curCk.MaxAge)
        gLogger.Info("Secure\t=%t", curCk.Secure)
        gLogger.Info("HttpOnly=%t", curCk.HttpOnly)
        gLogger.Info("Raw\t=%s", curCk.Raw)
        gLogger.Info("Unparsed=%s", curCk.Unparsed)
    }
}

func main() {
    initAll()

    gLogger.Info("this is EmulateLoginBaidu.go")

    //step1: access baidu url to get cookie BAIDUID
    var baiduMainUrl string
    baiduMainUrl = "http://www.baidu.com/";
    //baiduMainUrl := "http://www.baidu.com/";
    //var baiduMainUrl string = "http://www.baidu.com/";
    gLogger.Info("baiduMainUrl=%s", baiduMainUrl)
    respHtml := GetUrlRespHtml(baiduMainUrl)
    log4go.Debug("respHtml=%s", respHtml)
    //gLogger.Debug("respHtml=%s", respHtml)
    //printCurCookies()
    
    //gLogger.Error("why log can not show ????????")
    
    //var cookieNameListToCheck []string = ["BAIDUID"]
    //toCheckCookieNameList := [1]string{"BAIDUID"}
    toCheckCookieNameList := []string{"BAIDUID"}
    toCheckCookieNum := len(toCheckCookieNameList)
    gLogger.Info("toCheckCookieNum=%d\n", toCheckCookieNum) //toCheckCookieNum=1
    //fmt.Printf("toCheckCookieNum=%d\n", toCheckCookieNum) //toCheckCookieNum=1
    for i := 0; i < toCheckCookieNum; i++ {
        cookieName := toCheckCookieNameList[i];
        gLogger.Info("[%d]cookieName=%s", i, cookieName)
        //fmt.Printf("[%d]cookieName=%s\n", i, cookieName) //[0]cookieName=BAIDUID
    }
    
    deinitAll()
}

结果,竟然输出是:

console中,所有的打印信息,都没有了。。。

包括fmt的和log4go的。。。

全都是空的

而对应的log文件中,输出的是正的:

console all not show log file show ok

11.想办法,去删除log4go,再重新安装试试。

【记录】go语言中去卸载(之前已安装的)某个包(库)

然后接着还是问题依旧:

E:\Dev_Root\go\src\EmulateLoginBaidu>go run EmulateLoginBaidu.go

E:\Dev_Root\go\src\EmulateLoginBaidu>

12.此处,console和log文件:

log4go_debug_1.log

都是空的,都没有输出任何信息。

感觉像是:

要么是log4go,内部弄成死锁性质的,导致无法输出,或者是block掉了。

13.现在去试试:

只保留log4go中,初始化的console,去掉log文件的部分:

    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    //gLogger = make(log4go.Logger)
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    
    gLogger = log4go.NewDefaultLogger(log4go.INFO)
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    //gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))

看看结果如何:

问题依旧。

此刻,的确没有创建什么log文件了。

并且还是之前的:console中也无输出了。

14.反过来:保留log文件,去掉console:

    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    gLogger = make(log4go.Logger)
    
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger = log4go.NewDefaultLogger(log4go.INFO)
    
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))

看看结果如何:

结果是log文件:log4go_debug_1.log

虽然被创建了。

结果还是空的。

console中,自然还是没有输出。

15。看到:

Re: [go-nuts] log4go flush – msg#01802

这人,遇到和我,有点点类似的问题:

其要输出的hello world,由于程序的exit,导致无法输出了:正常的话,肯定是应该可以的。

那我此处,去试试,加上exit,看看什么效果。

//init for logger
func initLogger(){
    //var filenameOnly string
    //filenameOnly = GetCurFilename()
    //var logFilename string =  filenameOnly + ".log";
    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    gLogger = make(log4go.Logger)
    
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger = log4go.NewDefaultLogger(log4go.INFO)
    
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))
    exit();

    return
}

结果是:

根本没exit函数:

.\EmulateLoginBaidu.go:97: undefined: exit

16.换成log4go的close试试:

//init for logger
func initLogger(){
    //var filenameOnly string
    //filenameOnly = GetCurFilename()
    //var logFilename string =  filenameOnly + ".log";
    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    gLogger = make(log4go.Logger)
    
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger = log4go.NewDefaultLogger(log4go.INFO)
    
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))
    //exit();
    gLogger.Close();

    return
}

结果是:

问题依旧。

17.参考:

http://godoc.org/code.google.com/p/log4go#Exit

去试试:

    //gLogger.Close();
    log4go.Exit();

结果是:

问题依旧。

18.后来,看到了:

Abnormal behavior of log4go

中的解释:

(1)log4go的文档,很明显不是最新的,用的函数也是旧的函数:这点我早已发现,并且改正了;

(2)存在flush的bug,main函数退出太快的话,会导致无输出,或者输出内容部分丢失:我此处就是这样的问题。

(3)参考那人的解释,去手动加上flush的动作试试:

在main函数最后所调用的deinitAll函数中加上:

//de-init for all
func deinitAll(){
    gCurCookies = nil
    if(nil == gLogger) {
        gLogger.Close();
        os.Stdout.Sync() //try manually flush, hope can fix log4go's bug
        
        gLogger = nil
    }
}

看看效果:

结果还是无输出。。。

19.想起来了,此处是刚才把stdout禁止了。

现在去加上:

//init for logger
func initLogger(){
    //var filenameOnly string
    //filenameOnly = GetCurFilename()
    //var logFilename string =  filenameOnly + ".log";
    var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    //gLogger = make(log4go.Logger)
    
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    gLogger = log4go.NewDefaultLogger(log4go.INFO)
    
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))
    //exit();
    //gLogger.Close();
    //log4go.Exit();

    return
}

结果是:

问题依旧,还是无输出。。。

20.去试试,在main函数最后,加上sleep的代码:

    time.Sleep(1000 * time.Millisecond)

结果是

真的可以了!!!

after sleep can show all console and file log

即:

不论是log文件,还是console,都可以正常输出log信息了。。。

21.再去注释掉sleep的话:

//time.Sleep(1000 * time.Millisecond)

看看结果:

果然真的没有输出。

22.再去对于sleep时间改短点,比如只有100毫秒:

    //time.Sleep(1000 * time.Millisecond)
    time.Sleep(100 * time.Millisecond)

结果是:

也正常,可以输出去全部log信息。

23.继续去缩短sleep的时间,看看10毫秒如何:

    //time.Sleep(1000 * time.Millisecond)
    //time.Sleep(100 * time.Millisecond)
    time.Sleep(10 * time.Millisecond)

结果也是可以的。

再次证明:

log4go,的确是有bug;

而手动加stdout的sync是没用的

但是加上sleep就有用,

而且是sleep一个很短的时间,比如10毫秒,就足够了,就可以保证所有的log信息正常输出了。

24.再去把之前正常的代码,都加上:

/*
 * [File]
 * EmulateLoginBaidu.go
 * 
 * [Function]
 * 【记录】用go语言实现模拟登陆百度
 * http://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * http://www.crifan.com/about/me/
 */
package main

import (
    //"fmt"
    //"builtin"
    //"log"
    "os"
    "runtime"
    "path"
    "strings"
    "time"
    //"io"
    "io/ioutil"
    "net/http"
    //"net/http/cookiejar"
    //"sync"
    //"net/url"
)

//import l4g "log4go.googlecode.com/hg"
//import l4g "code.google.com/p/log4go"
import "code.google.com/p/log4go"

/***************************************************************************************************
    Global Variables
***************************************************************************************************/
var gCurCookies []*http.Cookie;
var gLogger log4go.Logger;

/***************************************************************************************************
    Functions
***************************************************************************************************/
//do init before all others
func initAll(){
    gCurCookies = nil
    gLogger = nil
    
    initLogger()
    initCrifanLib()
}

//de-init for all
func deinitAll(){
    gCurCookies = nil
    if(nil == gLogger) {
        gLogger.Close();
        //os.Stdout.Sync() //try manually flush, but can not fix log4go's flush bug
        
        gLogger = nil
    }
}

//do some init for crifanLib
func initCrifanLib(){
    gLogger.Debug("init for crifanLib")
    gCurCookies = nil
    return
}

//init for logger
func initLogger(){
    var filenameOnly string = GetCurFilename()
    var logFilename string =  filenameOnly + ".log";
    //var logFilename string =  "log4go_debug_1.log";
    
    //gLogger = log4go.NewLogger()
    //gLogger = make(log4go.Logger)
    
    //for console
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    //gLogger.AddFilter("stdout", log4go.INFO, log4go.NewConsoleLogWriter())
    gLogger = log4go.NewDefaultLogger(log4go.INFO)
    
    //for log file
    if _, err := os.Stat(logFilename); err == nil {
        //fmt.Printf("found old log file %s, now remove it\n", logFilename)
        os.Remove(logFilename)
    }
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, true))
    //gLogger.AddFilter("logfile", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.AddFilter("log", log4go.FINEST, log4go.NewFileLogWriter(logFilename, false))
    gLogger.Info("Current time is : %s", time.Now().Format("15:04:05 MST 2006/01/02"))
    
    return
}

// GetCurFilename
// Get current file name, without suffix
func GetCurFilename() string {
    _, fulleFilename, _, _ := runtime.Caller(0)
    //fmt.Println(fulleFilename)
    var filenameWithSuffix string
    filenameWithSuffix = path.Base(fulleFilename)
    //fmt.Println("filenameWithSuffix=", filenameWithSuffix)
    var fileSuffix string
    fileSuffix = path.Ext(filenameWithSuffix)
    //fmt.Println("fileSuffix=", fileSuffix)
    
    var filenameOnly string
    filenameOnly = strings.TrimSuffix(filenameWithSuffix, fileSuffix)
    //fmt.Println("filenameOnly=", filenameOnly)
    
    return filenameOnly
}

//get url response html
func GetUrlRespHtml(url string) string{
    gLogger.Info("GetUrlRespHtml, url=%s", url)
    
    var respHtml string = "";
    
    resp, err := http.Get(url)
    //gLogger.Info("http.Get done")
    if err != nil {
        gLogger.Warn("http get url=%s response error=%s\n", url, err.Error())
    }
    gLogger.Debug("resp.Header=%s", resp.Header)
    gLogger.Debug("resp.Status=%s", resp.Status)

    defer resp.Body.Close()
    // gLogger.Info("defer resp.Body.Close done")
    
    body, errReadAll := ioutil.ReadAll(resp.Body)
    //body, _ := ioutil.ReadAll(resp.Body)
    //fmt.Println("ioutil.ReadAll done")
    //fmt.Println("resp.Body.Close done")
    //gLogger.Info("ioutil.ReadAll done")
    //fmt.Println("gLogger.Info done")
    if errReadAll != nil {
        gLogger.Warn("get response for url=%s got error=%s\n", url, errReadAll.Error())
    }
    //gLogger.Debug("body=%s\n", body)

    gCurCookies = resp.Cookies()
    //gLogger.Info("resp.Cookies done")
    //fmt.Println("resp.Cookies done")
    
    //respHtml = "just for test log ok or not"
    respHtml = string(body)
    //gLogger.Info("resp body []byte to string done")

    return respHtml
}

func printCurCookies() {
    var cookieNum int = len(gCurCookies);
    gLogger.Info("cookieNum=%d", cookieNum)
    for i := 0; i < cookieNum; i++ {
        var curCk *http.Cookie = gCurCookies[i];
        //gLogger.Info("curCk.Raw=%s", curCk.Raw)
        gLogger.Info("------ Cookie [%d]------", i)
        gLogger.Info("Name\t=%s", curCk.Name)
        gLogger.Info("Value\t=%s", curCk.Value)
        gLogger.Info("Path\t=%s", curCk.Path)
        gLogger.Info("Domain\t=%s", curCk.Domain)
        gLogger.Info("Expires\t=%s", curCk.Expires)
        gLogger.Info("RawExpires=%s", curCk.RawExpires)
        gLogger.Info("MaxAge\t=%d", curCk.MaxAge)
        gLogger.Info("Secure\t=%t", curCk.Secure)
        gLogger.Info("HttpOnly=%t", curCk.HttpOnly)
        gLogger.Info("Raw\t=%s", curCk.Raw)
        gLogger.Info("Unparsed=%s", curCk.Unparsed)
    }
}

func main() {
    initAll()

    gLogger.Info("this is EmulateLoginBaidu.go")

    //step1: access baidu url to get cookie BAIDUID
    var baiduMainUrl string
    baiduMainUrl = "http://www.baidu.com/";
    //baiduMainUrl := "http://www.baidu.com/";
    //var baiduMainUrl string = "http://www.baidu.com/";
    gLogger.Info("baiduMainUrl=%s", baiduMainUrl)
    respHtml := GetUrlRespHtml(baiduMainUrl)
    gLogger.Debug("respHtml=%s", respHtml)
    printCurCookies()
    
    //gLogger.Error("why log can not show ????????")
    
    //var cookieNameListToCheck []string = ["BAIDUID"]
    //toCheckCookieNameList := [1]string{"BAIDUID"}
    toCheckCookieNameList := []string{"BAIDUID"}
    toCheckCookieNum := len(toCheckCookieNameList)
    gLogger.Info("toCheckCookieNum=%d", toCheckCookieNum) //toCheckCookieNum=1
    //fmt.Printf("toCheckCookieNum=%d\n", toCheckCookieNum) //toCheckCookieNum=1
    for i := 0; i < toCheckCookieNum; i++ {
        cookieName := toCheckCookieNameList[i];
        gLogger.Info("[%d]cookieName=%s", i, cookieName)
        //fmt.Printf("[%d]cookieName=%s\n", i, cookieName) //[0]cookieName=BAIDUID
    }
    
    deinitAll()

    //【workaround】go语言中用log4go输出信息时有bug:只输出部分信息,甚至是无任何输出
    //http://www.crifan.com/go_language_log4go_only_output_part_info/
    time.Sleep(10 * time.Millisecond)
}

看看结果是否也正常:

结果是:

偶尔,还是会输出内容不全的。

大部分的时候,已经正常了,够用了。

所以,看起来,至少此处的,sleep给的10ms,还是不太够。

所以,还是去改为更大点的时间,比如之前的100ms:

 

【总结】

至此,终于清楚根本原因了:

log4go,本身这个库还是不错的,

只不过,到目前为止:2013-09-20

还是有bug的,其中一个bug是:

其内部是通过channel去将log内容输出,到console和log文件中的;

而如果你的程序(main函数)退出的太快

就会导致log信息,来不及输出,你的程序就退出了。

从而导致:

你用log4go输出的信息,部分的,甚至全部的,都丢失了

从而在你的console和(或)你的log文件中,看不到log信息

解决办法:

在你的main函数,退出之前,加上对应的sleep,即可。

比如:

time.Sleep(100 * time.Millisecond)

即可保证:

你的log信息,都可以正常输出。

 

感慨:

log4go,不错的模块,可是这样的bug却浪费了我大量的时间。。。哎,无语。。。



2 Thoughts on “【workaround】go语言中用log4go输出信息时有bug:只输出部分信息,甚至是无任何输出

  1. log4go 的问题已经解决了。

    https://github.com/ccpaging/log4go

  2. 额,这个我也碰见过,看了下代码是因为channel的原因,包装一下等待channel写完再退出最好。
    比如在main里调用log.Write2Exit(),当然要加的东西很多。

    比如,你要先关闭你的channel,然后做一个标记关闭了(atomic),然后再调用Write2Exit(),判定写完,然后再return或者os.Exit()

发表评论

电子邮件地址不会被公开。 必填项已用*标注

无觅相关文章插件,快速提升流量