dcsimg
September 27, 2016
Hot Topics:

Using Go's Logger

By Matt Butcher and Matt Farina

This article was excerpted from the book Go in Practice.

Go provides two built-in packages for logging: "log" and "log/syslog". In this article, we'll talk about the main package first, "log."

The "log" package provides basic support (mainly in the form of formatting) for writing log messages. In its simplest usage, it formats messages and sends them to standard error.

Listing 1: Simple log usage

package main

import (
   "log"
)
func main() { log.Println("This is a regular
message.")       #A     log.Fatalln("This is a fatal
error.")         #1     log.Println("This is the end of the
function.")      #B }

#A Write a message to os.Stderr
#1 Write a message to os.Stderr and then exit with an error code
#B This never gets executed

If we were to run the code above, the output would look something like this:

$ go run simple.go
2015/04/27 08:18:36 This is a regular message.
2015/04/27 08:18:36 This is a fatal error. exit status 1

There are just a few things to point out about this example. The first is that the error messages are all sent to standard error, regardless of whether the actual message is an error or an informational message. In fact, if you take a glance at the godocs for the "log" package, you'll notice that it doesn't distinguish between message types. But it does make a second distinction, and that leads us to our other point.

When you call log.Fatalln or any of the other "fatal" calls, the library prints the error message and then calls os.Exit(1), forcing the program to quit. Additionally, there are log.Panic calls which log an error message and then issue a panic.

The log functions all have printf-style variants so that you can insert information into your log message string: log.Printf("The value of i is %s", i).

Practically speaking, we the authors have not found the basic logging functions to be all that useful. While there is some momentum in the Docker/container world behind logging to Standard Out and Standard Error, the prevailing wisdom seems to be that log messages should be sent to either a logging service or a designated file. To that end, we've gotten a lot more use out of the log.Logger type that is also in the package.

Technique 1 Logging to an Arbitrary Writer

Sending messages to standard error is useful for simple tools. When we are building servers, applications, or system services, we need a better place to send our log messages.Although you can write directly to the system log, here we will look at using the log package to write to any io.Writer.

PROBLEM

You want to send logging messages to a file or to a network sevice without having to write your own logging system.

SOLUTION

Initialize a new log.Logger and send log messages to that.

DISCUSSION

The log.Logger provides features for sending log data to any io.Writer, which includes things like file handles and network connections (net.Conn). Here is a brief example that illustrates setting up a log file and sending messages.

Listing 2: Logging to a file

package main

import (
   "log"
   "os"
)
func main() { logfile, _  :=
os.Create("./log.txt") #1  defer func() {
#A logfile.Close() #A  }()
#A

   logger := log.New(logfile, "example ",
      log.LstdFlags|log.Lshortfile) #2
   logger.Println("This is a regular  message.")
   #B   logger.Fatalln("This is a fatal error.")
   #B   logger.Println("This is the end of the function.")
   #C }

#1 Create a log file.
#A Make sure it gets closed.
#2 Create a logger.
#B Send it some messages.
#C As before, this will never get called.

The above example begins by creating a log file #1, and then using it as a destination for log messages #2.

NOTE: The way we set up this example, the logfile will get overwritten every time because we used os.Create #1. This is nice for our example, but you may want to open an existing log file instead of clobbering it.

When creating new log.Logger, there are three pieces of information you can pass to it #2. The first is the io.Writer where you want to send messages. The second is a prefix for log messages, and the third is a list of flags that determine the format of the log message. To understand the second and third, let's take a look at some sample log data from the log.txt file generated by the program above:

$ cat log.txt example 2015/05/12 08:42:51 outfile.go:16: This is a
regular message. example 2015/05/12 08:42:51 outfile.go:17: This is
a fatal error.

As before, only two of the three logger.Log calls succeeded because the second one also generated a fatal error. But we can see from the file how the Go logger logged the data. Roughly speaking, we can break a log message into three parts: the prefix, the automatically generated information, and the log message itself.

Go1
Figure 1: Components of a log file

You can control the prefix field with the second argument to log.New. As you may have noticed, when we created our logger #2 the prefix had a trailing whitespace ("example "). That was not an accident. By default, the logger does not put any space between the prefix and the generated data.

When it comes to the generated information, you do not have direct control over the information, but you have some degree of indirect control. For example, while you cannot format the date and time fields exactly as you would like, you can set some flags that determine how specific the log message is. When creating the log.Logger #2, the third argument is a bitmask of flags. As we saw above, we passed in the flags log.LstdFlags | log.Lshortfile. This set the date format and then also instructed the logger to show the file and line info. (You might notice that those are also bolded in the diagram above.)

For the most part, there are only two pieces of information that are automatically generated for you: Information about when the event happened, and information about where it happened. With the date and time information, you can set the precision of the timestamp:

  • Ldate controls printing the date.
  • Ltime prints the time stamp.
  • Lmicrosends adds microsecond precision to the time. This will automatically result in the time being printed, even if Ltime is not set.
  • LstdFlags simply turns on both Ldate and Ltime.
  • And then there are a pair of flags that deal with the location information:
  • Llongfile shows a full file path and then the line number: /foo/bar/baz.go:123.
  • Lshortifle shows just the filename and the line number: baz.go:123.

While you can OR flags together, there are combinations that are obviously incompatible  (namely, Llongfile and Lshortfile).

Logging to files is usually straightforward. But sometimes logging to different sources can introduce complexity.

Technique 2 Logging to a Network Resource

The previous technique showed how to log to a generic io.Writer. The code we wrote used a simple file as a destination for the log message. But these days many of the applications we write—especially servers—run in the cloud inside of Docker images, VMs, or other resources that have only ephemeral storage. Furthermore, we often run servers in clusters, where it is desirable to aggregate the logs of all servers onto one logging service.

Let's look at logging onto a network resource.

Many popular logging services, including Logstash and Heka aggregate logs. Such services typically expose a port to which you can connect and stream log messages. This style of logging has been popularized in the influential Twelve-Factor App paradigm whose 11th factor is "Treat logs as event streams." As simple as that all sounds, there are some bugaboos in sending log messages as streams.

PROBLEM

Streaming logs to a network service is error-prone, but we don't want to lose log messages if we can avoid it.

SOLUTION

Making use of Go's channels and some buffering, you can vastly improve reliability.

DISCUSSION

Before we can get going on the code, what we need is something that can simulate a log server for us. While setting up services like Hekad or Logstash is not terribly difficult, it's beyond the scope of this article. So instead, we will avail ourselves of a simple UNIX tool called Net Cat (nc). Net Cat ships standard on most UNIX and Linux flavors, including OSX. There's also a Windows version available.

We want to start a simple TCP server that accepts simple text messages and writes them to the console. This is a simple Net Cat command:

nc -lk 1902

Now we have a listener (-l) listening continuously (-k) on port 1902. This little command will do a fine job of simulating a log server.

Now we can get some code running by adapting our last example (Listing 2) to write to a network socket.

Listing 3: Network Log Client

package main

import (
   "log"
   "net"
)
func main() {

   conn, err := net.Dial("tcp", "localhost:1902")
   #1  if err != nil {panic("Failed to connect to
      localhost:1902")
   }
   defer func() { #2 conn.Close( #2 }()
   #2

   f :=   log.Ldate | log.Lshortfile
   logger := log.New(conn, "example ", f) #3

   logger.Println("This is a regular
   message.") logger.Panicln("This is a panic.")
#4 }

#1 Connect to the log server.
#2 Make sure we clean up by closing the connection, even on panic.
#3 Send log messages to the network connection.
#4 Log a message and then panic.

Surprisingly, not much needs to be changed to write to a network connection instead of a file. Go's network library is convenient and simple. We create a new TCP connection with net.Dial(), #1 connecting it to the port we opened with nc. It is always recommended to close a network connection in a defer block #2. If nothing else, when a panic occurs (like it will in this demo code), the network buffer will be flushed on close, and we are less likely to lose critical log messages telling us why the code paniced.

Again, we use the log package to log to the remote server #3. Using the logging package here gives us a few advantages. The first is that we get a time stamp for free, and when logging to a network server it's always a good idea to log the host time, and not rely solely on the log server's timestamp. This helps us reconstruct a record of events even if the log messages are delayed on their way to the log server. Second, as you can see by comparing Listing 2 and 3, when we stick with the logging system, it's easy to swap out the underlying log strorage mechanism. This is great for testing and running developer environments.

Did you notice that we also changed the log.Fatalln to a log.Panicln in this example? There is a simple reason for this: The log.Fatal* functions have an unfortunate side effect: the deferred function is not called. Why not? Because log.Fatal* calls os.Exit, which immediately terminates the program without unwinding the function stack. That means our network connection is never properly flushed and closed. Panics, on the other hand, are easier to capture. In reality, production code for anything but simple command line clients should avoid using fatal errors. And as we saw in the previous chapter, there are very specific cases in which you should call a panic.

With all of this in mind, when we execute the above code, our nc instance should receive some log messages:

$ nc -lk 1902 example 2015/05/27 log_client.go:23: This is a
regular message. example 2015/05/27 log_client.go:24: This is
a panic.

These messages made their way from our example client to the simple server we're running on nc. We've got a nice simple network logging utility. In high-traffic situations, you may look even further into optimizing network-based logging by buffering logs locally and then sending them over UDP connections instead of TCP. This helps avoid a network congestion problem known as backpressure.

Go2

Using Go's Logger

By Matt Butcher and Matt Farina

This article was excerpted from the book Go in Practice.


Tags: Unix, Go, logger, log message, Net Cat




Comment and Contribute

 


(Maximum characters: 1200). You have characters left.

 

 


Enterprise Development Update

Don't miss an article. Subscribe to our newsletter below.

Sitemap | Contact Us

Thanks for your registration, follow us on our social networks to keep up-to-date
Rocket Fuel