最新消息：20210816 当前crifan.com域名已被污染，为防止失联，请关注（页面右下角的）公众号
    你的位置：在路上 > 工作和技术 > ProgrammingLanguage > GO > 【workaround】go语言中用log4go输出信息时有bug：只输出部分信息，甚至是无任何输出

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

    GO crifan 4430浏览 0评论

    【问题】

    折腾：

    【记录】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：

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

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

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

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

    4.后来又经过一番调试，最后发现：

    现象是：

    虽然代码都是正常的：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    68
    69
    70
    71
    72
    73
    74
    75
    76
    77
    78
    79
    80
    81
    82
    83
    84
    85
    86
    87
    88
    89
    90
    91
    92
    93
    94
    95
    96
    97
    98
    99
    100
    101
    102
    103
    104
    105
    106
    107
    108
    109
    110
    111
    112
    113
    114
    115
    116
    117
    118
    119
    120
    121
    122
    123
    124
    125
    126
    127
    128
    129
    130
    131
    132
    133
    134
    135
    136
    137
    138
    139
    140
    141
    142
    143
    144
    145
    146
    147
    148
    149
    150
    151
    152
    153
    154
    155
    156
    157
    158
    159
    160
    161
    162
    163
    164
    165
    166
    167
    168
    169
    170
    171
    172
    173
    174
    175
    176
    177
    178
    179
    180
    181
    182
    183
    184
    185
    186
    187
    188
    189
    190
    191
    192
    193
    194
    195
    196
    197
    198
    199
    200
    201
    202
    203
    204
    205
    206
    207
    208
    209
    /*
     * [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文件，都是没了：

    console only show until resp cookies

    log file only show until resp status

    所以，很是奇怪。

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

    无法正常输出log信息。

    6.开始以为是：

    ?
    1
    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文件，看看能否正常输出：

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

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

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

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

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    68
    69
    70
    71
    72
    73
    74
    75
    76
    77
    78
    79
    80
    81
    82
    83
    84
    85
    86
    87
    88
    89
    90
    91
    92
    93
    94
    95
    96
    97
    98
    99
    100
    101
    102
    103
    104
    105
    106
    107
    108
    109
    110
    111
    112
    113
    114
    115
    116
    117
    118
    119
    120
    121
    122
    123
    124
    125
    126
    127
    128
    129
    130
    131
    132
    133
    134
    135
    136
    137
    138
    139
    140
    141
    142
    143
    144
    145
    146
    147
    148
    149
    150
    151
    152
    153
    154
    155
    156
    157
    158
    159
    160
    161
    162
    163
    164
    165
    166
    167
    168
    169
    170
    171
    172
    173
    174
    175
    176
    177
    178
    179
    180
    181
    182
    183
    184
    185
    186
    187
    188
    189
    190
    191
    192
    193
    194
    195
    196
    197
    198
    199
    200
    201
    202
    203
    204
    205
    206
    207
    208
    209
    210
    211
    212
    /*
     * [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文件中，输出的是正的：

    console all not show log file show ok

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

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

    然后接着还是问题依旧：

    ?
    1
    2
    3
    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文件的部分：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    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：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    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，看看什么效果。

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    //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函数：

    ?
    1
    .\EmulateLoginBaidu.go:97: undefined: exit

    16.换成log4go的close试试：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    //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

    去试试：

    ?
    1
    2
    //gLogger.Close();
    log4go.Exit();

    结果是：

    问题依旧。

    18.后来，看到了：

    Abnormal behavior of log4go

    中的解释：

    （1）log4go的文档，很明显不是最新的，用的函数也是旧的函数：这点我早已发现，并且改正了；

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

    （3）参考那人的解释，去手动加上flush的动作试试：

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

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    //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禁止了。

    现在去加上：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    //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的代码：

    ?
    1
    time.Sleep(1000 * time.Millisecond)

    结果是

    真的可以了！！！

    after sleep can show all console and file log

    即：

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

    21.再去注释掉sleep的话：

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

    看看结果：

    果然真的没有输出。

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

    ?
    1
    2
    //time.Sleep(1000 * time.Millisecond)
    time.Sleep(100 * time.Millisecond)

    结果是：

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

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

    ?
    1
    2
    3
    //time.Sleep(1000 * time.Millisecond)
    //time.Sleep(100 * time.Millisecond)
    time.Sleep(10 * time.Millisecond)

    结果也是可以的。

    再次证明：

    log4go，的确是有bug；

    而手动加stdout的sync是没用的

    但是加上sleep就有用，

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

    24.再去把之前正常的代码，都加上：

    ?
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    68
    69
    70
    71
    72
    73
    74
    75
    76
    77
    78
    79
    80
    81
    82
    83
    84
    85
    86
    87
    88
    89
    90
    91
    92
    93
    94
    95
    96
    97
    98
    99
    100
    101
    102
    103
    104
    105
    106
    107
    108
    109
    110
    111
    112
    113
    114
    115
    116
    117
    118
    119
    120
    121
    122
    123
    124
    125
    126
    127
    128
    129
    130
    131
    132
    133
    134
    135
    136
    137
    138
    139
    140
    141
    142
    143
    144
    145
    146
    147
    148
    149
    150
    151
    152
    153
    154
    155
    156
    157
    158
    159
    160
    161
    162
    163
    164
    165
    166
    167
    168
    169
    170
    171
    172
    173
    174
    175
    176
    177
    178
    179
    180
    181
    182
    183
    184
    185
    186
    187
    188
    189
    190
    191
    192
    193
    194
    195
    196
    197
    198
    199
    200
    201
    202
    203
    204
    205
    206
    207
    208
    209
    210
    211
    212
    213
    214
    /*
     * [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，即可。

    比如：

    ?
    1
    time.Sleep(100 * time.Millisecond)

    即可保证：

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

     

    感慨：

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

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

    Post Views: 1,596

    与本文相关的文章

    发表我的评论
    取消评论

    表情

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

    • 昵称 (必填)
    • 邮箱 (必填)
    • 网址

    网友最新评论 (2)

    1. log4go 的问题已经解决了。 https://github.com/ccpaging/log4go
      ccpaging10年前 (2015-01-06)回复
    2. 额，这个我也碰见过，看了下代码是因为channel的原因，包装一下等待channel写完再退出最好。 比如在main里调用log.Write2Exit()，当然要加的东西很多。 比如，你要先关闭你的channel，然后做一个标记关闭了(atomic)，然后再调用Write2Exit()，判定写完，然后再return或者os.Exit()
      steven11年前 (2014-04-01)回复
    85 queries in 0.208 seconds, using 22.28MB memory