natefinch / lumberjack

lumberjack is a log rolling package for Go
MIT License
4.79k stars 591 forks source link

Lumberjack loggers are not garbage-collected, which can leak file handles #81

Open nmiyake opened 5 years ago

nmiyake commented 5 years ago

Currently, every instance of a lumberjack logger that has ever performed a write will have an associated running goroutine. Because this goroutine references the logger, the logger is never garbage-collected, even if it otherwise goes out of scope. Because the logger holds a handle to the file it is logging to, this can leak file descriptors.

If #56 is fixed using the currently proposed solution, then calling Close() on the logger will stop the goroutine, which will allow it to be GC'd.

However, given that not all callers will call Close(), it would be nice to have a design where, if a logger is GC'd, that would ensure that the associated file handles would be closed.

The branch at https://github.com/jdhenke/lumberjack/tree/avoid-goroutine-cleanup demonstrates an approach that implements this fix. In this approach, the "mill" goroutine ends once its work is complete. Locks are used to ensure that only 1 mill routine is running for a logger at any given time, and subsequent requests will queue mill work.

The following test demonstrates the file handle GC behavior. This test fails with the current code, but succeeds on the branch linked above:

func TestFileHandleReleasedOnGC(t *testing.T) {
    dir := makeTempDir("TestFileHandleReleasedOnGC", t)
    defer os.RemoveAll(dir)
    filename := logFile(dir)

    equals(0, len(linesWithString(lsofOutput(t), ".log")), t)

    logger1 := &Logger{
        Filename: filename,
    }
    _, _ = logger1.Write([]byte("foo!"))

    equals(1, len(linesWithString(lsofOutput(t), ".log")), t)

    _ = logger1
    runtime.GC()

    // there should be no more references to the logger, so GC should have closed file handle
    equals(0, len(linesWithString(lsofOutput(t), ".log")), t)
}

func linesWithString(content, find string) []string {
    var output []string
    for _, line := range strings.Split(content, "\n") {
        if strings.Contains(line, find) {
            output = append(output, line)
        }
    }
    return output
}

func lsofOutput(t *testing.T) string {
    lsofOutput, err := exec.Command("lsof", "-p", strconv.Itoa(os.Getpid())).Output()
    require.NoError(t, err)
    return string(lsofOutput)
}

Another advantage of this approach is that a logger will only have a mill goroutine running when it is actively doing mill work (whereas currently every logger that has ever performed a write will have an associated goroutine).