Logging information

All UNIX systems have their own log files for writing logging information that comes from running servers and programs. Usually, most system log files of a UNIX system can be found under the /var/log directory. However, the log files of many popular services, such as Apache and Nginx, can be found elsewhere, depending on their configuration.

Logging and storing logging information in log files is a practical way of examining data and information from your software asynchronously, either locally, at a central log server, or using server software such as Elasticsearch, Beats, and Grafana Loki.

Generally speaking, using a log file to write some information used to be considered a better practice than writing the same output on screen for two reasons. Firstly, because the output does not get lost, as it is stored on a file, and secondly, because you can search and process log files using UNIX tools, such as grep(1), awk(1), and sed(1), which cannot be done when messages are printed in a terminal window. However, writing to log files is not always the best approach, mainly because many services run as Docker images, which have their own log files that get lost when the Docker image stops.

As we usually run our services via systemd, programs should log to stdout so that systemd can put logging data in the journal. https://12factor.net/logs offers more information about app logs. Additionally, in cloud-native applications, we are encouraged to simply log to stderr and let the container system redirect the stderr stream to the desired destination.

The UNIX logging service has support for two properties named logging level and logging facility. The logging level is a value that specifies the severity of the log entry. There are various logging levels, including debug, info, notice, warning, err, crit, alert, and emerg, in reverse order of severity. The log package of the standard Go library does not support working with logging levels. The logging facility is like a category used for logging information. The value of the logging facility part can be one of auth, authpriv, cron, daemon, kern, lpr, mail, mark, news, syslog, user, UUCP, local0, local1, local2, local3, local4, local5, local6, or local7 and is defined inside /etc/syslog.conf, /etc/rsyslog.conf, or another appropriate file depending on the server process used for system logging on your UNIX machine. This means that if a logging facility is not defined correctly, it will not be handled; therefore, the log messages you send to it might get ignored and, therefore, lost.

The log package sends log messages to standard error. Part of the log package is the log/syslog package, which allows you to send log messages to the syslog server of your machine. Although by default log writes to standard error, the use of log.SetOutput() modifies that behavior. The list of functions for sending logging data includes log.Printf(), log.Print(), log.Println(), log.Fatalf(), log.Fatalln(), log.Panic(), log.Panicln(), and log.Panicf().

Logging is for application code, not library code. If you are developing libraries, do not put logging in them.

In order to write to system logs, you need to call the syslog.New() function with the appropriate parameters. Writing to the main system log file is as easy as calling syslog.New() with the syslog.LOG_SYSLOG option. After that, you need to tell your Go program that all logging information goes to the new logger—this is implemented with a call to the log.SetOutput() function. The process is illustrated in the following code—type it into your favorite plain text editor and save it as systemLog.go:

package main
import (
    "log"
    "log/syslog"
)
func main() {
    sysLog, err := syslog.New(syslog.LOG_SYSLOG, "systemLog.go")
    if err != nil {
        log.Println(err)
        return
    } else {
        log.SetOutput(sysLog)
        log.Print("Everything is fine!")
    }
}

After the call to log.SetOutput(), all logging information goes to the syslog logger variable which sends it to syslog.LOG_SYSLOG. Custom text for the log entries coming from that program is specified as the second parameter to the syslog.New() call.

Usually, we want to store logging data in user-defined files because they group relevant information, which makes them easier to process and inspect.

Running systemLog.go generates no output. However, if you execute journalctl -xe on a Linux machine, you can see entries like the following:

Jun 08 20:46:05 thinkpad systemLog.go[4412]: 2023/06/08 20:46:05 Everything is fine!
Jun 08 20:46:51 thinkpad systemLog.go[4822]: 2023/06/08 20:46:51 Everything is fine!

The output on your own operating system might be slightly different, but the general idea is the same.

Bad things happen all the time, even to good people and good software. So the next subsection covers the Go way of dealing with bad situations.

log.Fatal() and log.Panic()

The log.Fatal() function is used when something erroneous has happened and you just want to exit your program as soon as possible after reporting that bad situation. The call to log.Fatal() terminates a Go program at the point where log.Fatal() was called after printing an error message. In most cases, this custom error message can be Not enough arguments, Cannot access file, or similar. Additionally, it returns a non-zero exit code, which in UNIX indicates an error.

There are situations where a program is about to fail for good and you want to have as much information about the failure as possible—log.Panic() implies that something really unexpected and unknown, such as not being able to find a file that was previously accessed or not having enough disk space, has happened. Analogous to the log.Fatal() function, log.Panic() prints a custom message and immediately terminates the Go program.

Keep in mind that log.Panic() is equivalent to a call to log.Print(), followed by a call to panic(). This is a built-in function that stops the execution of the current function and begins panicking. After that, it returns to the caller function. Conversely, log.Fatal() calls log.Print() and then os.Exit(1), which is an immediate way of terminating the current program. Both log.Fatal() and log.Panic() are illustrated in the logs.go file, which contains the following Go code:

package main
import (
    "log"
    "os"
)
func main() {
    if len(os.Args) != 1 {
        log.Fatal("Fatal: Hello World!")
    }
    log.Panic("Panic: Hello World!")
}

If you call logs.go without any command line arguments, it calls log.Panic(). Otherwise, it calls log.Fatal(). This is illustrated in the following output from an Arch Linux system:

$ go run logs.go
2023/06/08 20:48:42 Panic: Hello World!
panic: Panic: Hello World!
goroutine 1 [running]:
log.Panic({0xc000104f60?, 0x0?, 0x0?})
    /usr/lib/go/src/log/log.go:384 +0x65
main.main()
    /home/mtsouk/code/mGo4th/ch01/logs.go:12 +0x85
exit status 2
$ go run logs.go 1
2023/06/08 20:48:59 Fatal: Hello World!
exit status 1

So the output of log.Panic() includes additional low-level information that, hopefully, will help you resolve difficult situations that arise in your Go code.

Please keep in mind that both of these functions terminate the program abruptly, which may not be what the user wants. As a result, they are not the best way to end a program. However, they can be handy for reporting really bad error conditions or unexpected situations. Two such examples are when a program is unable to save its data or when a configuration file is not found.

The next subsection is about writing to custom log files.

Writing to a custom log file

Most of the time, and especially on applications and services that are deployed to production, you need to write your logging data in a log file of your choice. This can be for many reasons, including writing debugging data without messing with the system log files, or keeping your own logging data separate from system logs to transfer it or store it in a database or software, like Elasticsearch. This subsection teaches you how to write to a custom log file that is usually application-specific.

Writing to files and file input and output are both covered in Chapter 7, Telling a UNIX System What to Do—however, saving information to files is very handy when troubleshooting and debugging Go code, which is why this is covered in the first chapter.

The path of the log file (mGo.log) that is used is stored on a variable named LOGFILE—this is created using the os.TempDir() function, which returns the default directory used on the current OS for temporary files, in order to prevent your file system from getting full in case something goes wrong.

Additionally, at this point, this will save you from having to execute customLog.go with root privileges and putting unnecessary files into precious system directories.

Type the following code and save it as customLog.go:

package main
import (
    "fmt"
    "log"
    "os"
    "path"
)
func main() {
    LOGFILE := path.Join(os.TempDir(), "mGo.log")
    fmt.Println(LOGFILE)
    f, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
// The call to os.OpenFile() creates the log file for writing, 
// if it does not already exist, or opens it for writing 
// by appending new data at the end of it (os.O_APPEND)
    if err != nil {
        fmt.Println(err)
        return
    }
    defer f.Close()

The defer keyword tells Go to execute the statement just before the current function returns. This means that f.Close() is going to be executed just before main() returns. We will go into more detail on defer in Chapter 6, Go Packages and Functions:

    iLog := log.New(f, "iLog ", log.LstdFlags)
    iLog.Println("Hello there!")
    iLog.Println("Mastering Go 4th edition!")
}

The last three statements create a new log file based on an opened file (f) and write two messages to it, using Println().

If you ever decide to use the code of customLog.go in a real application, you should change the path stored in LOGFILE to something that makes more sense.

Running customLog.go on an Arch Linux machine prints the file path of the log file:

$ go run customLog.go
/tmp/mGo.log

Depending on your operating system, your output might vary. However, what is important is what has been written in the custom log file:

$ cat /tmp/mGo.log
iLog 2023/11/27 22:15:10 Hello there!
iLog 2023/11/27 22:15:10 Mastering Go 4th edition!

The next subsection shows how to print line numbers in log entries.

Printing line numbers in log entries

In this subsection, you will learn how to print the filename as well as the line number in the source file where the statement that wrote a log entry is located.

The desired functionality is implemented with the use of log.Lshortfile in the parameters of log.New() or SetFlags(). The log.Lshortfile flag adds the filename as well as the line number of the Go statement that printed the log entry in the log entry itself. If you use log.Llongfile instead of log.Lshortfile, then you get the full path of the Go source file—usually, this is not necessary, especially when you have a really long path.

Type the following code and save it as customLogLineNumber.go:

package main
import (
    "fmt"
    "log"
    "os"
    "path"
)
func main() {
    LOGFILE := path.Join(os.TempDir(), "mGo.log")
    fmt.Println(LOGFILE)
    f, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
    if err != nil {
        fmt.Println(err)
        return
    }
    defer f.Close()
    LstdFlags := log.Ldate | log.Lshortfile
    iLog := log.New(f, "LNum ", LstdFlags)
    iLog.Println("Mastering Go, 4th edition!")
    iLog.SetFlags(log.Lshortfile | log.LstdFlags)
    iLog.Println("Another log entry!")
}

In case you are wondering, you are allowed to change the format of the log entries during program execution—this means that when there is a reason, you can print more analytical information in the log entries. This is implemented with multiple calls to iLog.SetFlags().

Running customLogLineNumber.go generates the following output:

$ go run customLogLineNumber.go
/var/folders/sk/ltk8cnw50lzdtr2hxcj5sv2m0000gn/T/mGo.log

It also writes the following entries in the file path that is specified by the value of the LOGFILE global variable:

$ cat /var/folders/sk/ltk8cnw50lzdtr2hxcj5sv2m0000gn/T/mGo.log
LNum 2023/06/08 customLogLineNumber.go:25: Mastering Go, 4th edition!
LNum 2023/06/08 20:58:09 customLogLineNumber.go:28: Another log entry!

The first error message is from source code line 25, whereas the second one is from source code line 28.

You will most likely get a different output on your own machine, which is the expected behavior.

Writing to multiple log files

This subsection shows a technique for writing to multiple log files—this is illustrated in multipleLogs.go, which can be found in the GitHub repository of the book under directory ch01 and comes with the following code:

package main
import (
    "fmt"
    "io"
    "log"
    "os"
)
func main() {
    flag := os.O_APPEND | os.O_CREATE | os.O_WRONLY
    file, err := os.OpenFile("myLog.log", flag, 0644)
    if err != nil {
        fmt.Println(err)
        os.Exit(0)
    }
    defer file.Close()
    w := io.MultiWriter(file, os.Stderr)
    logger := log.New(w, "myApp: ", log.LstdFlags)
    logger.Printf("BOOK %d", os.Getpid())
}

The io.MultiWriter() function is what allows us to write to multiple destinations, which in this case are a file named myLog.log and standard error.

The results of running multipleLogs.go can be seen in the myLog.log file, which is going to be created in the current working directory, and to standard error, which is usually presented on screen:

$ go run multipleLogs.go
myApp: 2023/06/24 21:02:55 BOOK 71457

The contents of myLog.log are the same as before:

$ at myLog.log
myApp: 2023/06/24 21:02:55 BOOK 71457

In the next section, we are going to write the first version of the statistics application.