As with most things in Go, where there's something satisfactory and extensible in the core page, it can be taken to the next level by a third party—Go's wonderful logging package is truly brought to life with log4go.
Using log4go greatly simplifies the process of file logging, console logging, and logging via TCP/UDP.
Tip
For more information on log4go, visit https://code.google.com/p/log4go/.
Each instance of a log4go Logger interface can be configured by an XML configuration file and can have filters applied to it to dictate where messaging goes. Let's look at a simple HTTP server to show how we can direct specific logs to location, as shown in the following code:
package main import ( "code.google.com/p/log4go" "net/http" "fmt" "github.com/gorilla/mux" ) var errorLog log4go.Logger var errorLogWriter log4go.FileLogWriter var accessLog log4go.Logger var accessLogWriter *log4go.FileLogWriter var screenLog log4go.Logger var networkLog log4go.Logger
In the preceding code, we created four distinct log objects—one that writes errors to a logfile, one that writes accesses (page requests) to a separate file, one that sends directly to console (for important notices), and one that passes a log message across the network.
The last two obviously do not need FileLogWriter, although it's entirely possible to replicate the network logging using a shared drive if we can mitigate issues with concurrent access, as shown in the following code:
func init() {
fmt.Println("Web Server Starting")
}
func pageHandler(w http.ResponseWriter, r *http.Request) {
pageFoundMessage := "Page found: " + r.URL.Path
accessLog.Info(pageFoundMessage)
networkLog.Info(pageFoundMessage)
w.Write([]byte("Valid page"))
}Any request to a valid page goes here, sending the message to the web-access.log file accessLog.
func notFound(w http.ResponseWriter, r *http.Request) {
pageNotFoundMessage := "Page not found / 404: " + r.URL.Path
errorLog.Info(pageNotFoundMessage)
w.Write([]byte("Page not found"))
}As with the accessLog file, we'll take any 404 / page not found request and route it directly to the notFound() method, which saves a fairly generic error message along with the invalid / missing URL requested. Let's look at what we'll do with extremely important errors and messages in the following code:
func restricted(w http.ResponseWriter, r *http.Request) {
message := "Restricted directory access attempt!"
errorLog.Info(message)
accessLog.Info(message)
screenLog.Info(message)
networkLog.Info(message)
w.Write([]byte("Restricted!"))
}The restricted() function and corresponding screenLog represents a message we deem as critical and worthy of going to not only the error and the access logs, but also to screen and passed across the wire as a networkLog item. In other words, it's a message so important that everybody gets it.
In this case, we're detecting attempts to get at our .git folder, which is a fairly common accidental security vulnerability that people have been known to commit in automatic file uploads and updates. Since we have cleartext passwords represented in files and may expose that to the outside world, we'll catch this on request and pass to our critical and noncritical logging mechanisms.
We might also look at this as a more open-ended bad request notifier—one worthy of immediate attention from a network developer. In the following code, we'll start creating a few loggers:
func main() {
screenLog = make(log4go.Logger)
screenLog.AddFilter("stdout", log4go.DEBUG, log4go.NewConsoleLogWriter())
errorLogWriter := log4go.NewFileLogWriter("web-errors.log",
false)
errorLogWriter.SetFormat("%d %t - %M (%S)")
errorLogWriter.SetRotate(false)
errorLogWriter.SetRotateSize(0)
errorLogWriter.SetRotateLines(0)
errorLogWriter.SetRotateDaily(true)Since log4go opens up a bevy of additional logging options, we can play a bit with how our logs rotate and are formatted without having to draw that out specifically with Sprintf or something similar.
The options here are simple and expressive:
SetFormat: This allows us to specify how our individual log lines will look.SetRotate: This permits automatic rotation based on the size of the file and/or the number of lines inlog. TheSetRotateSize()option sets rotation on bytes in the message andSetRotateLines()sets the maximum number oflines.TheSetRotateDaily()function lets us create new logfiles based on the day regardless of our settings in the previous functions. This is a fairly common logging technique and can generally be burdensome to code by hand.
The output of our logging format ends up looking like the following line of code:
04/13/14 10:46 - Page found%!(EXTRA string=/valid) (main.pageHandler:24)
The %S part is the source, and that gives us the line number and our method trace for the part of our application that invoked the log:
errorLog = make(log4go.Logger)
errorLog.AddFilter("file", log4go.DEBUG, errorLogWriter)
networkLog = make(log4go.Logger)
networkLog.AddFilter("network", log4go.DEBUG, log4go.NewSocketLogWriter("tcp", "localhost:3000"))Our network log sends JSON-encoded messages via TCP to the address we provide. We'll show a very simple handling server for this in the next section of code that translates the log messages into a centralized logfile:
accessLogWriter = log4go.NewFileLogWriter("web-access.log",false)
accessLogWriter.SetFormat("%d %t - %M (%S)")
accessLogWriter.SetRotate(true)
accessLogWriter.SetRotateSize(0)
accessLogWriter.SetRotateLines(500)
accessLogWriter.SetRotateDaily(false)Our accessLogWriter is similar to the errorLogWriter except that instead of rotating daily, we rotate it every 500 lines. The idea here is that access logs would of course be more frequently touched than an error log—hopefully. The code is as follows:
accessLog = make(log4go.Logger)
accessLog.AddFilter("file",log4go.DEBUG,accessLogWriter)
rtr := mux.NewRouter()
rtr.HandleFunc("/valid", pageHandler)
rtr.HandleFunc("/.git/", restricted)
rtr.NotFoundHandler = http.HandlerFunc(notFound)In the preceding code, we used the Gorilla Mux package for routing. This gives us easier access to the 404 handler, which is less than simplistic to modify in the basic http package built directly into Go. The code is as follows:
http.Handle("/", rtr)
http.ListenAndServe(":8080", nil)
}Building the receiving end of a network logging system like this is also incredibly simple in Go, as we're building nothing more than another TCP client that can handle the JSON-encoded messages.
We can do this with a receiving server that looks remarkably similar to our TCP chat server from an earlier chapter. The code is as follows:
package main
import
(
"net"
"fmt"
)
type Connection struct {
}
func (c Connection) Listen(l net.Listener) {
for {
conn,_ := l.Accept()
go c.logListen(conn)
}
}As with our chat server, we bind our listener to a Connection struct, as shown in the following code:
func (c *Connection) logListen(conn net.Conn) {
for {
buf := make([]byte, 1024)
n, _ := conn.Read(buf)
fmt.Println("Log Message",string(n))
}
}In the preceding code, we receive log messages delivered via JSON. At this point, we're not unmarshalling the JSON, but we've shown how to do that in an earlier chapter.
Any message sent will be pushed into the buffer—for this reason, it may make sense to expand the buffer's size depending on how detailed the information is.
func main() {
serverClosed := make(chan bool)
listener, err := net.Listen("tcp", ":3000")
if err != nil {
fmt.Println ("Could not start server!",err)
}
Conn := Connection{}
go Conn.Listen(listener)
<-serverClosed
}You can imagine how network logging can be useful, particularly in server clusters where you might have a selection of, say, web servers and you don't want to reconcile individual logfiles into a single log.
With all the discussion of capturing errors and logging them, we should probably consider the panic() and recover() functionality in Go.
As briefly discussed earlier, panic() and recover() operate as a more basic, immediate, and explicit error detection methodology than, say, try/catch/finally or even Go's built-in error return value convention. As designed, panic() unwinds the stack and leads to program exit unless recover() is invoked. This means that unless you explicitly recover, your application will end.
So, how is this useful other than for stopping execution? After all, we can catch an error and simply end the application manually through something similar to the following code:
package main
import
(
"fmt"
"os"
)
func processNumber(un int) {
if un < 1 || un > 4 {
fmt.Println("Now you've done it!")
os.Exit(1)
}else {
fmt.Println("Good, you can read simple instructions.")
}
}
func main() {
userNum := 0
fmt.Println("Enter a number between 1 and 4.")
_,err := fmt.Scanf("%d",&userNum)
if err != nil {}
processNumber(userNum)
}However, while this function does sanity checking and enacts a permanent, irreversible application exit, panic() and recover() allow us to reflect errors from a specific package and/or method, save those, and then resume gracefully.
This is very useful when we're dealing with methods that are called from other methods that are called from other methods, and so on. The types of deeply embedded or recursive functions that make it hard to discern a specific error are where panic() and recover() are most advantageous. You can also imagine how well this functionality can play with logging.
The panic() function on its own is fairly simple, and it really becomes useful when paired with recover() and defer().
Take, for example, an application that returns meta information about a file from the command line. The main part of the application will listen for user input, pass this into a function that will open the file, and then pass that file reference to another function that will get the file's details.
Now, we can obviously stack errors as return elements straight through the process, or we can panic along the way, recover back down the steps, and gather our errors at the bottom for logging and/or reporting directly to console.
Avoiding spaghetti code is a welcomed side effect of this approach versus the former one. Think of this in a general sense (this is pseudo code):
func getFileDetails(fileName string) error {
return err
}
func openFile(fileName string) error {
details,err := getFileDetails(fileName)
return err
}
func main() {
file,err := openFile(fileName)
}With a single error, it's entirely manageable to approach our application in this way. However, when each individual function has one or more points of failure, we will require more and more return values and a way of reconciling them all into a single overall error message or messages. Check the following code:
package main
import
(
"os"
"fmt"
"strconv"
)
func gatherPanics() {
if rec := recover(); rec != nil {
fmt.Println("Critical Error:", rec)
}
}This is our general recovery function, which is called before every method on which we wish to capture any panic. Let's look at a function to deduce the file's details:
func getFileDetails(fileName string) {
defer gatherPanics()
finfo,err := os.Stat(fileName)
if err != nil {
panic("Cannot access file")
}else {
fmt.Println("Size: ", strconv.FormatInt(finfo.Size(),10))
}
}
func openFile(fileName string) {
defer gatherPanics()
if _, err := os.Stat(fileName); err != nil {
panic("File does not exist")
}
}The two functions from the preceding code are merely an attempt to open a file and panic if the file does not exist. The second method, getFileDetails(), is called from the main() function such that it will always execute, regardless of a blocking error in openFile().
In the real world, we will often develop applications where a nonfatal error stops just a portion of the application from working, but will not cause the application as a whole to break. Check the following code:
func main() {
var fileName string
fmt.Print("Enter filename>")
_,err := fmt.Scanf("%s",&fileName)
if err != nil {}
fmt.Println("Getting info for",fileName)
openFile(fileName)
getFileDetails(fileName)
}If we were to remove the recover() code from our gatherPanics() method, the application would crash if/when the file didn't exist.
This may seem ideal, but imagine a scenario where a user selects a nonexistent file for a directory that they lack the rights to view. When they solve the first problem, they will be presented with the second instead of seeing all potential issues at one time.
The value of expressive errors can't be overstated from a user experience standpoint. Gathering and presenting expressive errors is made easier through this methodology—even a try/catch/finally requires that we (as developers) explicitly do something with the returned error in the catch clause.
In the preceding code, we can integrate a logging mechanism pretty simply in addition to catching our panics.
One consideration about logging that we haven't discussed is the notion of when to log. As our previous examples illustrate, we can sometimes run into problems that should be logged but may be mitigated by future user action. As such, we can choose to log our errors immediately or save it until the end of execution or a greater function.
The primary benefit of logging immediately is that we're not susceptible to an actual crash preventing our log from being saved. Take the following example:
type LogItem struct {
Message string
Function string
}
var Logs []LogItemWe've created a log struct and a slice of LogItems using the following code:
func SaveLogs() {
logFile := log4go.NewFileLogWriter("errors.log",false)
logFile.SetFormat("%d %t - %M (%S)")
logFile.SetRotate(true)
logFile.SetRotateSize(0)
logFile.SetRotateLines(500)
logFile.SetRotateDaily(false)
errorLog := make(log4go.Logger)
errorLog.AddFilter("file",log4go.DEBUG,logFile)
for i:= range Logs {
errorLog.Info(Logs[i].Message + " in " + Logs[i].Function)
}
}This, ostensibly, is where all of our captured LogItems will be turned into a good collection of line items in a logfile. There is a problem, however, as illustrated in the following code:
func registerError(block chan bool) {
Log := LogItem{ Message:"An Error Has Occurred!", Function: "registerError()"}
Logs = append(Logs,Log)
block <- true
}Executed in a goroutine, this function is non-blocking and allows the main thread's execution to continue. The problem is with the following code that runs after the goroutine, which causes us to log nothing at all:
func separateFunction() {
panic("Application quitting!")
}Whether invoked manually or by the binary itself, the application quitting prematurely precludes our logfiles from being written, as that method is deferred until the end of the main() method. The code is as follows:
func main() {
block := make(chan bool)
defer SaveLogs()
go func(block chan bool) {
registerError(block)
}(block)
separateFunction()
}The tradeoff here, however, is performance. If we execute a file operation every time we want to log something, we're potentially introducing a bottleneck into our application. In the preceding code, errors are sent via goroutine but written in blocking code—if we introduce the log writing directly into registerError(), it can slow down our final application.
As mentioned previously, one opportunity to mitigate these issues and allow the application to still save all of our log entries is to utilize either memory logging or network logging.
In earlier Go releases, the ability to properly execute a stack trace from our source was a daunting task, which is emblematic of some of the many complaints and concerns users had early on about general error handling in Go.
While the Go team has remained vigilant about the right way to do this (as they have with several other key language features such as a lack of generics), stack traces and stack info have been tweaked a bit as the language has grown.