Logging in Go

For real-world programs, logging is a tool to record useful information such as events and messages. This is beneficial for monitoring, debugging, or troubleshooting issues. By analyzing log data, developers and system administrators can gain insights into system behavior, identify problems, and track the flow of executions.

What needs to be logged can vary based on the requirements of the application. Logs typically include runtime errors, warnings, debugging information, network statuses, etc. In this topic, you will learn how to use Golang's log package to set up efficient logging in your programs.

Logging 101 in Golang

In Go, the log package provides essential tools for logging. It revolves around a predefined Logger type, a struct representing an active logging object that writes output to an io.Writer interface. By default, the Logger prints to standard error and includes the date and time in each log message.

The Logger type contains three families of helper methods: Print, Fatal, and Panic.

• Print – It consists of the Print, Printf, and Println methods; the arguments are handled similarly to their counterparts in the fmt package, and they print to the standard error.

• Fatal – It includes Fatal, Fatalf, and Fatalln; these methods log the message and then terminate the program using os.Exit(1). They are used for fatal errors where the program cannot continue.

• Panic – It contains Panic, Panicf, and Panicln; these methods log the message and then trigger a panic. They are suitable when an error is severe enough to halt the program.

Now, let's look at a logging example. The following program has a function, calculateQuantity, that takes two arguments: totalCost and unitCost. This function attempts to estimate the quantity by dividing the total cost by the unit cost:

package main

import (
    "fmt"
    "log"
)

func calculateQuantity(totalCost, unitCost float64) (float64, error) {
    if unitCost == 0 {
        return 0, fmt.Errorf("calculateQuantity: unitCost cannot be zero")
    }
    return totalCost / unitCost, nil
}

func main() {
    quantity, err := calculateQuantity(8, 3)
    if err != nil {
        log.Fatal(err)
    }
    log.Println("Result is", quantity)
}

The output looks as follows:

2023/12/24 01:36:13 Result is 2.6666666666666665

If a user passed 0 as the unitCost, then you would see the following error output and the program would immediately exit:

2023/12/24 01:37:20 calculateQuantity: unitCost cannot be zero

Now that you've learned the basics of logging, let's look at some scenarios where we might want to customize log messages.

Setting flags in logging

Flags in the log package allow you to enrich the format of your log messages. By default, Logger includes the date and time in the output. However, it is possible to log more information, such as file names, line numbers, or even custom prefixes, which can provide more context for debugging.

The flags in the log package are internally defined integer constants that facilitate different formats when applied. Some of the common flags are log.Ldate and log.Ltime, used to define the date and time in log messages. You can configure flags for the logger using the SetFlags() function and even combine them using the bitwise OR | operator.

Apart from setting flags, you can also use the SetPrefix() function to append a unique string prefix to the Logger, helping to identify its logs distinctly.

To further demonstrate how to set flags and prefixes, let's extend the previous example and customize the logger to display an INFO: prefix, along with the date, filename, and line number:

package main

import (
	"fmt"
	"log"
)

func calculateQuantity(totalCost, unitCost float64) (float64, error) {
    if unitCost == 0 {
        return 0, fmt.Errorf("calculateQuantity: unitCost cannot be zero")
    }
    return totalCost / unitCost, nil
}

func main() {
    // Customize the default `Logger`
    log.SetPrefix("INFO: ") // Setting a prefix for the log messages
    log.SetFlags(log.Ldate | log.Lshortfile) // Include date & filename/line num 
    
    quantity, err := calculateQuantity(8, 3)
    if err != nil {
        log.Fatal(err)
    }
    log.Println("Result is", quantity)
}

Now, the log output looks as follows—it includes the INFO: prefix, date, filename hello.go, and line number, which is the 24th line:

INFO: 2023/12/24 hello.go:24: Result is 2.6666666666666665

Logging to files

Logging to stdout/stderr is useful for small programs, but as programs get more complex, writing logs to a file for later analysis and diagnosis can be helpful. File-based logs can be further analyzed and monitored with automated tools to identify any concerns with program execution. It's important to note that logs written to stderr are often used for diagnostic messages and errors, while file-based logs are better suited for recording a broader range of runtime information, including operational data and audit trails.

Now, let's take a look at how to write logs to a file in Go:

package main

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

func calculateQuantity(totalCost, unitCost float64) (float64, error) {
    if unitCost == 0 {
        return 0, fmt.Errorf("calculateQuantity: unitCost cannot be zero")
    }
    return totalCost / unitCost, nil
}

func main() {
    // Opening a file for logging
    file, err := os.OpenFile("app.log", os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
    if err != nil {
        log.Fatal(err)
    }
    defer file.Close()
    log.SetOutput(file) // Changing the output of the `Logger` to a file

    // Customize the default `Logger`
    log.SetPrefix("INFO: ")                 
    log.SetFlags(log.Ldate | log.Lshortfile)

    quantity, err := calculateQuantity(8, 3)
    if err != nil {
        log.Fatal(err)
    }
    log.Println("Result is", quantity)
}

In the above example, the outputs are written to the app.log file. To achieve this, we first open the file in write-only mode with appropriate flags for creating or appending. We use defer file.Close() to ensure resource cleanup. After opening the log file, we employ the log.SetOutput() function to redirect the logger's output to that file. This sequence guarantees that the logger begins writing to the file from the start of the program.

Custom logger and config-based logging

Now, it's time to look at a real-world use case where logging is driven by configuration using custom loggers. Custom loggers provide flexibility in log messages that vary in verbosity, format, etc. You can enable custom loggers by configuring them through environment variables or application configuration files.

Environment variables are dynamic values that can affect the behavior of processes and applications running on a computer's operating system. These variables are part of the environment in which a process runs and provide a convenient way to pass configuration information to applications. In Go, you can use the os.Getenv() function to retrieve values from these environment variables.

Apart from retrieving the environment variables, we will use the log.New() function to create custom level-based loggers (INFO and DEBUG). For the INFO logger, we will record the date and time with the prefix INFO:, while for the DEBUG logger, we will include the filename and line number with the prefix DEBUG:.

Let's take a look at the code. (Note the filename is hello.go here, and we will refer to it when running it via the terminal):

package main

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

func calculateQuantity(totalCost, unitCost float64) (float64, error) {
    if unitCost == 0 {
        return 0, fmt.Errorf("calculateQuantity: unitCost cannot be zero")
    }
    return totalCost / unitCost, nil
}

func main() {
    // Open or create the log file
    file, err := os.OpenFile("app.log", os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
    if err != nil {
        log.Fatal(err)
    }
    defer file.Close()

    // Setting up different loggers for INFO and DEBUG levels
    infoLogger := log.New(file, "INFO: ", log.Ldate|log.Ltime)
    debugLogger := log.New(os.Stdout, "DEBUG: ", log.Ldate|log.Ltime|log.Lshortfile)

    quantity, err := calculateQuantity(8, 3)
    if err != nil {
        log.Fatal(err)
    }
    infoLogger.Println("Result is", quantity) // Info logging

    // Debug logging if ENV variable is set to DEBUG
    if os.Getenv("ENV") == "DEBUG" {
        debugLogger.Printf("Input value received: totalCost=%v, unitCost=%v, result=%v\n",
            8, 3, quantity)
    }
}

You can run the above code via the export ENV=DEBUG && go run hello.go command. The export ENV=DEBUG sets the environment variable to the value DEBUG before executing the Go program, and you can see the output in the terminal as follows:

$ export ENV=DEBUG && go run hello.go
DEBUG: 2023/12/24 3:33:11 main.go:36: Input value received: totalCost=8, unitCost=3, result=2.6666666666666665

Finally, we will check the contents of the app.log file using the cat command:

$ cat app.log 
INFO: 2023/12/24 03:33:13 Result is 2.6666666666666665

Conclusion

We've taken a tour of Golang's log package and explored its various features. We've learned how to log a basic message, change the format of the logged message, and customize logger creation based on environment variables. This is a good start. As always, there are more points to explore, such as:

• Application logging via configuration files, using assets such as Viper, a Golang package designed for reading config files.

• Asynchronous logging, which allows logging without blocking the code execution.

• Adding custom loggers as first-class objects to the library.

• Incorporating more contextual information into logging for enhanced observability.

Now it's time to test your understanding of logging with some theoretical and coding tasks. Let's go!