Chapter 4. Logging Recipes

4.0 Introduction

Logging is the act of recording events that occur during the running of a program. It is often an undervalued activity in programming because it is additional work that has little immediate payback for the programmer.

During the normal operations of a program, logging is an overhead, taking up processing cycles to write to a file, database, or even to the screen. In addition, unmanaged logs can cause problems. The classic case of logfiles getting so big that they take up all the available disk space and crash the server is too real and happens too often.

However, when something happens, and you want to find out the sequence of events that led to it, logs become an invaluable diagnostic resource. Logs can also be monitored in real time, and alerts can be sent out when needed.

4.1 Writing to Logs

Problem

You want to log events that happen during the execution of your code.

Solution

Use the log package in the standard library to log events.

Discussion

Go provides a log package in the standard library that you can use to log events while the program is running. It has a default implementation that writes to standard error and adds a timestamp. This means you can use it out of the box for logging without configuration or setup if you’re looking to log to standard error.

The log package provides several functions that allow you to write logs. In particular, there are three sets of functions:

Print: Prints the logs to the logger
Fatal: Prints to the logger and calls os.Exit with an exit code of 1
Panic: Prints to the logger and calls panic

Each set comes in a triplet of functions; for example, Print has Print and Printf, which allow formatting, and Println adds a newline after printing.

Here is an example with Print:

func main() {
	str := "abcdefghi"
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Println("Cannot parse string:", err)
	}
	fmt.Println("Number is", num)
}

In this example, when you encounter an error, you call the Println function that prints to the standard logger. You will see this on the command line when you run the program:

% go run main.go
2022/01/23 18:39:06 Cannot parse string: strconv.ParseInt: parsing "abcdefghi":
 invalid syntax
Number is 0

You will also see that the program doesn’t stop and continues to the final statement of the program. In other words, Println simply logs and continues. How is it different from fmt.Println? It’s not, really—the only thing it adds to the line is the date.

Next, take a look at Fatal. You change just one line of the code to use Fatalln:

func main() {
	str := "abcdefghi"
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Fatalln("Cannot parse string", err)
	}
	fmt.Println("Number is", num)
}

When you run it, you should see this:

% go run main.go
2022/01/23 18:42:10 Cannot parse string strconv.ParseInt: parsing "abcdefghi":
invalid syntax
exit status 1

Notice that the final statement isn’t executed, and the program ends with exit code 1. Exit code 1 is a catch-all for general errors, meaning something went wrong with the program, and that’s why it has to exit.

Finally, you can use Panic. When you call the panic built-in function, it will halt the current goroutine, run the deferred code, and return to the calling function, triggering another panic, which bubbles up eventually to main and finally exits. Refer to Recipe 3.7 for more on the built-in panic function:

func main() {
	str := "abcdefghi"
	num := conv(str)
	fmt.Println("Number is", num)
}

func conv(str string) (num int64) {
	defer fmt.Println("deferred code in function conv")
	num, err := strconv.ParseInt(str, 10, 64)
	if err != nil {
		log.Panicln("Cannot parse string", err)
	}
	fmt.Println("end of function conv")
	return
}

The Panicln function prints to the standard logger and panics. When you run the code, this is what you will see:

% go run main.go
2022/01/23 18:48:20 Cannot parse string strconv.ParseInt: parsing "abcdefghi":
invalid syntax
deferred code in function conv
panic: Cannot parse string strconv.ParseInt: parsing "abcdefghi": invalid syntax
...
exit status 2

The deferred code in the conv function runs, but the final statement in the program doesn’t. Interestingly you see exit code 2, which is technically inaccurate because traditionally, exit code 2 means something like “incorrect arguments.” As of Go version 1.17.6 this minor bug is still in the backlog, waiting to be fixed.

4.2 Change What Is Being Logged by the Standard Logger

Problem

You want to change what the standard logger logs.

Solution

Use the SetFlags function to set flags and add fields to each log line.

Discussion

The default behavior of the standard logger adds the date and time fields to each line of the log. For example, with this line of code:

log.Println("Some event happened")

you will see this on the screen:

2022/01/24 10:46:44 Some event happened

The log package allows you to add information along with the default date and time fields. You can add these fields using the SetFlag function. The fields that are provided include:

Date: The date in local time zone
Time: The time in local time zone
Microseconds: The microsecond resolution of the time field
UTC: Use UTC time zone instead of local time zone if date or time fields are set
Long file: The full filename and line number
Short file: The filename and the line number
Message prefix position: Move the prefix (from SetPrefix) from the beginning of the line to before the start of the message

Here are some examples. You start by setting only the date field in the log:

log.SetFlags(log.Ldate)
log.Println("Some event happened")

This produces:

2022/01/24 Some event happened

If you want to add the time with microsecond details, you do this:

log.SetFlags(log.Ldate | log.Lmicroseconds)
log.Println("Some event happened")

Using the or operator on the flags, you set up the various fields to use with the log. Here’s the result from before:

2022/01/24 20:43:54.595365 Some event happened

The file fields are interesting because you can use them to tell you where the problems lie in the code through the logs:

log.SetFlags(log.Ldate | log.Lshortfile)
log.Println("Some event happened")

It gives you additional information about the filename and the line where the problem occurred:

2022/01/24 20:51:02 logging.go:20: Some event happened

4.3 Logging to File

Problem

You want to log events to a logfile instead of standard error.

Solution

Use the SetOutput function to set the log to write to a file.

Discussion

So far, you’ve learned about writing the logs to standard error, mainly on the screen if you run it in the command line. What if you want to write it to a logfile, which is common in most cases?

The answer is pretty simple. You use SetOutput to redirect the output to a file.

First, look at the logfile. You want to open a new file for create or append, and it’s for write only:

file, err := os.OpenFile("app.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
if err != nil {
    log.Fatal(err)
}
defer file.Close()

You call SetOutput with the file as the parameter, then continue to log:

log.SetOutput(file)
log.Println("Some event happened")

The output will be written to the app.log file instead of the screen.

As you probably realize from the code, setting up the logs to be written to file should be done once. What if you want to write to the screen and the file simultaneously? You could reset the log output each time (don’t do this) or maybe create two loggers, one for standard error and another for a file, then call the loggers in separate statements.

Or you can use Go’s MultiWriter function in the io package, which creates a writer that duplicates its writes to all the provided writers:

file, err := os.OpenFile("app.log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
if err != nil {
    log.Fatal(err)
}
defer file.Close()
writer := io.MultiWriter(os.Stderr, file)
log.SetOutput(writer)
log.Println("Some event happened")
log.Println("Another event happened")

Doing this will write to both the screen and the file simultaneously. In fact, you can write to more than two writers!

4.4 Using Log Levels

Problem

You want to log events according to log levels.

Solution

Use the New function to create a logger, one for each log level, and then use those loggers accordingly.

Discussion

Log data is usually pretty large. You can use log levels to make it more manageable and determine the priority of the events. Log levels indicate the event’s severity, indicating the event’s importance. It’s a simple mechanism—you look at the higher-severity log levels first, filtering off lower-level logs and reducing alert fatigue. Examples of log levels from high to low are:

Fatal
Error
Warn
Info
Debug

To set up log levels for your logs, you can add the level to each line of the log. The most straightforward way of doing this is to use the SetPrefix function:

log.SetPrefix("INFO ")
log.Println("Some event happened")

If you call the SetPrefix function with the log level as the prefix, you will set the log level at the beginning of the line:

INFO 2022/01/26 00:48:15 Some event happened

Of course, the problem is that each time you want to add a log line with a different log level from the previous line, you need to call SetPrefix again. That is not a feasible solution.

Another method is to create new loggers upfront, with each logger representing a single log level:

var (
	info  *log.Logger
	debug *log.Logger
)

func init() {
	info = log.New(os.Stderr, "INFO\t", log.LstdFlags)
	debug = log.New(os.Stderr, "DEBUG\t", log.LstdFlags)
}

To do this, you use the New function, which returns a logger, but you can also set the prefix and the fields to add to the log.

All you need to do to log events with different log levels is to use the appropriate loggers:

info.Println("Some informational event happened")
debug.Println("Some debugging event happened")

This is what will appear on the screen:

INFO	2022/01/26 00:53:03 Some informational event happened
DEBUG	2022/01/26 00:53:03 Some debugging event happened

You can also turn off logging for specific log levels to reduce the logfile size. For example, when you’re developing the program you can log debug events, but once you run in production, you no longer want to do that. A common practice is to use environment variables to indicate if you are running in development or production.

Environment variables are named values that are part of the environment in which programs run. Environment variables are set at the command line, and programs can access these variables during runtime.

For example, for Unix-based systems like Linux and macOS, you can set an environment variable ENV like this:

$ export ENV=development

To get the environment variable at the command line, you can use echo and add a $ in front of the variable name:

$ echo $ENV

Similarly, in Windows systems, you can set the environment variable this way:

$ set ENV=development

To get the environment variable in Windows, you can use echo and add a % before and after the variable name:

$ echo %ENV%

Retrieving the environment variable in Go is simple. You can use the os.Getenv function, passing it the environment variable name, and you will get the environment variable value. Using the same previous example, let’s set the ENV environment variable to production:

$ export ENV=production

If you run this code, you will see that the debug event is not printed:

info.Println("Some informational event happened")
if os.Getenv("ENV") != "production" {
	debug.Println("Some debugging event happened")
}

If you switch to the development environment, the debug event is printed again.

At the start of this recipe, you learned that one of the reasons to use log levels is to prioritize and filter off certain log levels. You can do this easily with a Unix-based system using the grep command.

Say you have a file named logfile.log with the following entries:

INFO	2023/01/06 00:21:32 Some informational event happened
DEBUG	2023/01/06 00:21:32 Some debugging event happened
INFO	2023/01/06 00:21:35 Another informational event happened
WARN	2023/01/06 00:23:35 A warning event happened
WARN	2023/01/06 00:33:11 Another warning event happened
ERROR	2023/01/06 00:33:11 An error event happened

You want to look at all error events first so you can use grep to filter out only error events:

$ grep "^ERROR" logfile.log

You will see only the error event. The ^ in front of grep means you just want to see the lines that start with ERROR:

ERROR	2023/01/06 00:33:11 An error event happened

What if you want to see all log events except for debug events? You can just exclude the debug events using the v flag in grep:

$ grep -v "^DEBUG" logfile.log

This will result in all events being shown except for debug events:

INFO	2023/01/06 00:21:32 Some informational event happened
INFO	2023/01/06 00:21:35 Another informational event happened
WARN	2023/01/06 00:23:35 A warning event happened
WARN	2023/01/06 00:33:11 Another warning event happened
ERROR	2023/01/06 00:33:11 An error event happened

Using grep is only the beginning. grep is a powerful tool, but there are many other log analysis tools you can use.

4.5 Logging to the System Log Service

Problem

You want to log in to the system log instead of your logfiles.

Solution

Use the log/syslog package to write to syslog.

Discussion

Syslog is a standard network-based logging protocol. It has long been the de facto standard for logging system events and was created by Eric Allman in the 1980s as part of the Sendmail project. The protocol was documented in RFC 3164 by the Internet Engineering Task Force (IETF). Subsequently, IETF standardized it in RFC 5424.

A syslog message (as in RFC 3164) consists of three parts:

Priority: Includes the facility and the severity
Header: Includes the timestamp and the hostname or IP address of the machine
Message: Includes the tag and the content

The facility describes the type of system that sends the log message. It allows log messages from different facilities to be handled differently. There are 24 facilities defined by the RFCs; here are a few:

0 (kernel)
1 (user-level)
2 (mail)
3 (system daemons)
4 (security/authorization messages)

The severity level is similar to the log level. Syslog defines eight different levels, with 0 being the highest and 7 being the lowest:

0 (Emergency)
1 (Alert)
2 (Critical)
3 (Error)
4 (Warning)
5 (Notice)
6 (Informational)
7 (Debug)

The timestamp and the hostname or IP address are self-explanatory. The tag is the name of the program that generated the message, while the content is the details of the log message.

Syslog is not implemented uniformly in different operating systems. A popular implementation of syslog is rsyslog, the default syslog implementation in many Linux variants including Debian, Ubuntu, openSUSE, and others.

Go provides a log/syslog package as part of the standard library to interface with syslog. However, it doesn’t work on all systems. For example, it doesn’t work with Windows because it’s not implemented on Windows.

The example in this recipe is based on running against rsyslog on Ubuntu 20.04, and it should work on systems with rsyslog. However, I have not tried it on all systems and implementations.

Before we start on the Go code, you need to set up rsyslog to show the priority, header, and message parts. In rsyslog this is done using a template in the rsyslog configuration file.

Start by editing the /etc/rsyslog.conf configuration file:

$ sudo vi /etc/rsyslog.conf

Add the template configuration after this line— $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat in the configuration file:

$template gosyslogs,"%syslogseverity-text% %syslogfacility-text% %hostname%
%timegenerated% %syslogtag% %msg%\n"
$ActionFileDefaultTemplate gosyslogs

In this configuration, you name the template gosyslogs. You set it to show the severity first, followed by the facility, then the hostname and the timestamp, and finally, the tag and message.

Once you save this file, restart rsyslog:

sudo service rsyslog restart

Now that you have set up rsyslog, you can look at the code. Sending log messages to syslog using the syslog package is relatively straightforward:

var logger *log.Logger

func init() {
	var err error
	logger, err = syslog.NewLogger(syslog.LOG_USER|syslog.LOG_NOTICE, 0)
	if err != nil {
		log.Fatal("cannot write to syslog: ", err)
	}
}

func main() {
	logger.Print("hello syslog!")
}

You use the NewLogger function to create a logger, passing the syslog priority flags you want to set. The syslog package provides flags for the facility and the severity levels. You can or them together to send the facility code and the severity level. For the case of the preceding code, you send in syslog.LOG_USER indicating the user facility code, and syslog.LOG_NOTICE indicating the notice severity level.

Run the code first in the file named main.go:

$ go run main.go

Now check the syslogs. Run this on the command line:

$ sudo tail /var/log/syslog

You should see a bunch of log messages, but somewhere at the bottom, you should see something like this:

notice user myhostname Jan 26 15:30:08 /tmp/go-build2223050573/b001/exe/
main[163995]:
  hello syslog!

The first field is notice, the severity level, followed by user, which is the facility code. Next is myhostname, which is the hostname, followed by the timestamp.

The next field is the tag, which is the /tmp/go-build2223050573/b001/exe/main[163995] field in the log message. Why is it indicating that it’s in the /tmp directory? That’s because you’re using go run. It will look different if you compile the code and run the binary file. The final field in the log message is the details of the log, which you print out using logger.

Get Go Cookbook now with the O’Reilly learning platform.

O’Reilly members experience books, live events, courses curated by job role, and more from O’Reilly and nearly 200 top publishers.

Start your free trial

Go Cookbook by Sau Sheong Chang

Chapter 4. Logging Recipes

4.0 Introduction

4.1 Writing to Logs

Problem

Solution

Discussion

4.2 Change What Is Being Logged by the Standard Logger

Problem

Solution

Discussion

4.3 Logging to File

Problem

Solution

Discussion

4.4 Using Log Levels

Problem

Solution

Discussion

4.5 Logging to the System Log Service

Problem

Solution

Discussion

Don’t leave empty-handed

It’s yours, free.

Check it out now on O’Reilly