【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语言实现模拟登陆百度
 * https://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * https://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文件，都是没了：

所以，很是奇怪。

至少，看起来，是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语言实现模拟登陆百度
 * https://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * https://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文件中，输出的是正的：

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)

结果是

真的可以了！！！

即：

不论是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语言实现模拟登陆百度
 * https://www.crifan.com/emulate_login_baidu_using_go_language/
 * 
 * [Version]
 * 2013-09-19
 *
 * [Contact]
 * https://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：只输出部分信息，甚至是无任何输出
    //https://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却浪费了我大量的时间。。。哎，无语。。。

转载请注明：在路上 » 【workaround】go语言中用log4go输出信息时有bug：只输出部分信息，甚至是无任何输出

Post Views: 1,454

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

func (ConsoleLogWriter) LogWrite

与本文相关的文章

Hi，您需要填写昵称和邮箱！

网友最新评论 (2)