Proper pattern to encapsulate log setup in golang

Question

When trying to move log setup code into a separate function I ran into inability to hide the destination file object from the main function. In the following INCORRECT simplified example the attempt is made to setup log writing to both Stderr and a file via a single function call:

package main

import (
    "io"
    "log"
    "os"
)

func SetupLogging() {
    logFile, err := os.OpenFile("test.log", os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        log.Panicln(err)
    }
    defer logFile.Close()

    log.SetOutput(io.MultiWriter(os.Stderr, logFile))
}

func main() {
    SetupLogging()
    log.Println("Test message")
}

Clearly is does not work because defer closes the log file at the end of the SetupLogging function.

A working example below adds extra code and IMHO looses some clarity if repeated in a larger application as a pattern:

package main

import (
    "io"
    "log"
    "os"
)

func SetupLogging() *os.File {
    logFile, err := os.OpenFile("test.log", os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        log.Panicln(err)
    }

    log.SetOutput(io.MultiWriter(os.Stderr, logFile))
    return logFile
}

func main() {
    logf := SetupLogging()
    defer logf.Close()

    log.Println("Test message")
}

Is there a different way to fully encapsulate open file management into a function, yet still nicely release the handle?

Answer 1

I have now successfully used the below approach for about a year in multiple projects. The idea is to return a function from the setup call. That resulting function contains the destruction logic. Here is an example:

package main

import (
    "fmt"
    "io"
    "log"
    "os"
)

func LogSetupAndDestruct() func() {
    logFile, err := os.OpenFile("test.log", os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666)
    if err != nil {
        log.Panicln(err)
    }

    log.SetOutput(io.MultiWriter(os.Stderr, logFile))

    return func() {
        e := logFile.Close()
        if e != nil {
            fmt.Fprintf(os.Stderr, "Problem closing the log file: %s\n", e)
        }
    }
}

func main() {
    defer LogSetupAndDestruct()()

    log.Println("Test message")
}

It is using a closure around the cleanup logic being deferred.

A somewhat more elaborate public example of using this approach is in the Viper code: here is the return from a test initializer, and here it is used to encapsulate the cleanup logic and objects

Answer 2

The proper way of doing this is passing the handle in main to SetupLogging:

func SetupLogging(lf *os.File) {
    log.SetOutput(io.MultiWriter(os.Stderr, logFile))
    log.Println("Started")
}

func main() {
    logFile, err := os.OpenFile("test.log", os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        log.Panicln(err)
    }
    defer logFile.Close()
    SetupLogging(logFile)
    log.Println("Test message")
}

Another option is to use runtime.SetFinalizer, but it's not always guaranteed to run before main exits.

func SetupLogging() {
    logFile, err := os.OpenFile("test.log", os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        log.Panicln(err)
    }
    runtime.SetFinalizer(logFile, func(h *os.File) {
        h.Close()
    })

    log.SetOutput(io.MultiWriter(os.Stderr, logFile))
}

Answer 3

You can do this using channels, here is my approach

type InfoLog struct {
    InfoChan chan string
    CloseChan chan struct{} //empty signal
    log *log.Logger
    file *os.File
}

func NewInfoLog(file *os.File) *InfoLog {
    return &InfoLog{
        InfoChan: make(chan string),
        CloseChan: make(chan struct{}),
        log: log.New(file, "TAG", log.Ldate|log.Ltime),
        file: file,
    }
}

func (i *InfoLog) listen() {
    for {
        select {
        case infoMsg := <-i.InfoChan:
            i.log.Println(infoMsg)
        case <-i.CloseChan:
            i.file.Close()
            close(i.InfoChan)
        }
    }
}

then in main

func main() {
    infoLog := NewInfoLog(ANY_OPEN_FILE_HERE)
    go infoLog.listen()
    infoLog.InfoChan <- "msg"
    infoLog.InfoChan <- "msg"
    infoLog.InfoChan <- "msg"
    infoLog.CloseChan <- struct{}{}
    // exits normaly
}

you can see an asynchronous log system i have made for a complete example: https://github.com/sescobb27/ciudad-gourmet/blob/master/services/log_service.go

Answer 4

in case where multiple "teardown" processes are needed, great solution to this is using google context package (https://blog.golang.org/context). advantage is that you can teardown all currently executing procedures with single context. smth like this:

package main

import (
    "fmt"
    "io"
    "log"
    "os"

    "golang.org/x/net/context"
)

func LogSetup(ctx context.Context) error {
    logFile, err := os.OpenFile("test.log", os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666)
    if err != nil {
        return err
    }

    log.SetOutput(io.MultiWriter(os.Stderr, logFile))
    // here we could f.ex. execute:
    // sendLogOutputToExternalService(ctx)
    // and it could have it's own teardown procedure
    // which would be called on main context's expiration
    go func() {
       for _ = range ctx.Done() {
         err := logFile.Close()
         if err = nil {
             fmt.Fprintf(os.Stderr, "Problem closing the log file: %s\n", e)
        }
    }()
    return nil
}


func main() {
    var stopAll func()
    mainContext, stopAll = context.WithCancel(context.Background())
    defer stopAll()

    err := LogSetup(mainContext)
    if err!=nil {
        log.Fatal("error while initializing logging") 
    }

    log.Println("Test message")
}