rollingfile lost log

[orange-jacky]

hi,dear I hava log.xml,

<seelog type="adaptive" mininterval="1000" maxinterval="1000000" critmsgcount="100" minlevel="info">

i find that my info.log when rolling lost some content.

now the size of info.log is 4.5M, after rolling at hour, it comes 70 bytes meanwhile, at 2017.1.6 15hour, the size of info.log is 50M, when at 16hour, it rolling the info.log to info.log.2017-01-06-16, but the size comes to 70byte.

and anyone can tell me how to fix it? best wishes

[lwithers]

Hi,

I've been running this little test program overnight:

package main

import (
        "time"

        "github.com/cihub/seelog"
)

func main() {
        lg, err := seelog.LoggerFromConfigAsBytes([]byte(`
<seelog type="adaptive" mininterval="1000" maxinterval="1000000" critmsgcount="100" minlevel="info">
<outputs formatid="all">
    <filter levels="debug">
        <rollingfile type="date" filename="logs/debug/debug.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="info">
        <rollingfile type="date" filename="logs/info/info.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="warn">
        <rollingfile type="date" filename="logs/warn/warn.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="error">
        <rollingfile type="date" filename="logs/error/error.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
</outputs>
<formats>
    <format id="all" format="%Date %Time %Lev %File.%Line %Msg%n"/>
</formats>
</seelog>
        `))
        if err != nil {
                panic(err)
        }

        var i int
        for {
                time.Sleep(time.Second)
                lg.Infof("a small log entry, #%d", i)
                i++
        }
}

and I haven't hit any issues:

Every 300.0s: ls -lh                                                                                          Sun Jan  8 11:26:40 2017

total 4.0M
-rw-r--r-- 1 lwithers lwithers 102K Jan  8 11:26 info.log
-rw-r--r-- 1 lwithers lwithers 185K Jan  7 18:59 info.log.2017-01-07-18
-rw-r--r-- 1 lwithers lwithers 225K Jan  7 19:59 info.log.2017-01-07-19
-rw-r--r-- 1 lwithers lwithers 226K Jan  7 20:59 info.log.2017-01-07-20
-rw-r--r-- 1 lwithers lwithers 229K Jan  7 21:59 info.log.2017-01-07-21
-rw-r--r-- 1 lwithers lwithers 229K Jan  7 22:59 info.log.2017-01-07-22
-rw-r--r-- 1 lwithers lwithers 229K Jan  7 23:59 info.log.2017-01-07-23
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 00:59 info.log.2017-01-08-00
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 01:59 info.log.2017-01-08-01
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 02:59 info.log.2017-01-08-02
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 03:59 info.log.2017-01-08-03
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 04:59 info.log.2017-01-08-04
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 05:59 info.log.2017-01-08-05
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 06:59 info.log.2017-01-08-06
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 07:59 info.log.2017-01-08-07
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 08:59 info.log.2017-01-08-08
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 09:59 info.log.2017-01-08-09
-rw-r--r-- 1 lwithers lwithers 229K Jan  8 10:59 info.log.2017-01-08-10

Is it at all possible that what you're seeing is the normal behaviour of the application? i.e. that some hours there were very few log entries relative to other hours?

Also, is it at all possible that you have two processes writing to the same set of files? That would almost certainly lead to files getting overwritten.

[orange-jacky]

@lwithers thanks for your reply. In fact, I create some goroutines to write the same info.log, can you tell me how to fix it ?

[lwithers]

Just to confirm, I have been able to reproduce this issue when using multiple goroutines:

package main

import (
        "time"

        "github.com/cihub/seelog"
)

func main() {
        lg, err := seelog.LoggerFromConfigAsBytes([]byte(`
<seelog type="adaptive" mininterval="1000" maxinterval="1000000" critmsgcount="100" minlevel="info">
<outputs formatid="all">
    <filter levels="debug">
        <rollingfile type="date" filename="logs/debug/debug.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="info">
        <rollingfile type="date" filename="logs/info/info.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="warn">
        <rollingfile type="date" filename="logs/warn/warn.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
    <filter levels="error">
        <rollingfile type="date" filename="logs/error/error.log" datepattern="2006-01-02-15" maxrolls="240"/>
    </filter>
</outputs>
<formats>
    <format id="all" format="%Date %Time %Lev %File.%Line %Msg%n"/>
</formats>
</seelog>
        `))
        if err != nil {
                panic(err)
        }
        seelog.ReplaceLogger(lg)

        go testRoutine()
        go testRoutine()
        testRoutine()
}

func testRoutine() {
        var i int
        for {
                seelog.Infof("a small log entry, #%d", i)
                i++
                ns := time.Duration(time.Now().Nanosecond())
                time.Sleep(time.Second - ns)
        }
}

 $ ls -lh
total 64K
-rw-r--r-- 1 lwithers lwithers 44K Jan  9 13:03 info.log
-rw-r--r-- 1 lwithers lwithers  63 Jan  9 09:59 info.log.2017-01-09-09
-rw-r--r-- 1 lwithers lwithers  64 Jan  9 10:59 info.log.2017-01-09-10
-rw-r--r-- 1 lwithers lwithers  64 Jan  9 11:59 info.log.2017-01-09-11
-rw-r--r-- 1 lwithers lwithers  65 Jan  9 12:59 info.log.2017-01-09-12
 $ cat info.log.2017-01-09-11
2017-01-09 12:00:00 Inf testdate.go.44 a small log entry, #8100

So, it seems to me that there must be a race condition in there somewhere. If I get a chance I'll take a closer look at the code and see if I can spot it.

[lwithers]

OK, the problem is that rollingFileWriter.Write() is called concurrently in the different goroutines — and, since there's no mutex, multiple goroutines may decide to roll the file simultaneously.

The simple solution is to add a mutex to the rollingFileWriter struct and to lock it during Write(). It could be better for performance to test for and perform the file rolling asynchronously. I'll open a PR with the simple solution for now.

[orange-jacky]

@lwithers thanks. i will wait for updating it and apply it. I have another issue, please hlep me check it.

in my another program, i configure log.xml as the over log.xml

<seelog type="adaptive" mininterval="1000" maxinterval="1000000" critmsgcount="100" minlevel="info">

but, i find it output the following content

hope your reply