Writing to log files

The log package allows you to send log messages to the system logging service of your UNIX machine, whereas the syslog Go package, which is part of the log package, allows you to define the logging level and the logging facility your Go program will use.

Usually, most system log files of a UNIX OS 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.

Generally speaking, using a log file to write some information is considered a better practice than writing the same output on the 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 on a terminal window.

The log package offers many functions for sending output to the syslog server of a UNIX machine. The list of functions includes log.Printf(), log.Print(), log.Println(), log.Fatalf(), log.Fatalln(), log.Panic(), log.Panicln(), and log.Panicf().

Please note that logging functions can be extremely handy for debugging your programs, especially server processes written in Go, so you should not underestimate their power.

Logging levels

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.

Logging facilities

A 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 and therefore handled, the log messages you send to it might get ignored and therefore lost.

Log servers

All UNIX machines have a separate server process that is responsible for receiving logging data and writing it to log files. There are various log servers that work on UNIX machines. However, only two of them are used on most UNIX variants: syslogd(8) and rsyslogd(8).

On macOS machines, the name of the process is syslogd(8). On the other hand, most Linux machines use rsyslogd(8), which is an improved and more reliable version of syslogd(8), which was the original UNIX system utility for message logging.

However, despite the UNIX variant you are using or the name of the server process used for logging, logging works the same way on every UNIX machine and therefore does not affect the Go code that you will write.

The configuration file of rsyslogd(8) is usually named rsyslog.conf and is located in /etc. The contents of a rsyslog.conf configuration file, without the lines with comments and lines starting with $, might look like the following:

$ grep -v '^#' /etc/rsyslog.conf | grep -v '^$' | grep -v '^\$'
auth,authpriv.*               /var/log/auth.log
*.*;auth,authpriv.none        -/var/log/syslog
daemon.*                      -/var/log/daemon.log
kern.*                        -/var/log/kern.log
lpr.*                         -/var/log/lpr.log
mail.*                        -/var/log/mail.log
user.*                        -/var/log/user.log
mail.info                     -/var/log/mail.info
mail.warn                     -/var/log/mail.warn
mail.err                      /var/log/mail.err
news.crit                     /var/log/news/news.crit
news.err                      /var/log/news/news.err
news.notice                   -/var/log/news/news.notice
*.=debug;\
    auth,authpriv.none;\
    news.none;mail.none       -/var/log/debug
*.=info;*.=notice;*.=warn;\
    auth,authpriv.none;\
    cron,daemon.none;\
    mail,news.none            -/var/log/messages
*.emerg                :omusrmsg:*
daemon.*;mail.*;\
    news.err;\
    *.=debug;*.=info;\
    *.=notice;*.=warn    |/dev/xconsole
local7.* /var/log/cisco.log

So, in order to send your logging information to /var/log/cisco.log, you will need to use the local7 logging facility. The star character after the name of the facility tells the logging server to catch every logging level that goes to the local7 logging facility and write it to /var/log/cisco.log.

The syslogd(8) server has a pretty similar configuration file that is usually /etc/syslog.conf. On macOS High Sierra, the /etc/syslog.conf file is almost empty and has been replaced by /etc/asl.conf. Nevertheless, the logic behind the configuration of /etc/syslog.conf, /etc/rsyslog.conf, and /etc/asl.conf is the same.

A Go program that sends information to log files

The Go code of logFiles.go will explain the use of the log and log/syslog packages to write to the system log files.

Please note that the log/syslog package is not implemented on the Microsoft Windows version of Go.

The first part of logFiles.go is as follows:

package main 
 
import ( 
    "fmt" 
    "log" 
    "log/syslog" 
    "os" 
    "path/filepath" 
) 
 
func main() { 
    programName := filepath.Base(os.Args[0]) 
    sysLog, err := syslog.New(syslog.LOG_INFO|syslog.LOG_LOCAL7, 
 programName)

The first parameter to the syslog.New() function is the priority, which is a combination of the logging facility and the logging level. Therefore, a priority of LOG_NOTICE | LOG_MAIL, which is mentioned as an example, will send notice logging level messages to the MAIL logging facility.

As a result, the preceding code sets the default logging to the local7 logging facility using the info logging level. The second parameter to the syslog.New() function is the name of the process that will appear on the logs as the sender of the message. Generally speaking, it is considered a good practice to use the real name of the executable in order to be able to easily find the information you want in the log files at another time.

The second part of the program contains the following Go code:

    if err != nil { 
        log.Fatal(err) 
    } else { 
        log.SetOutput(sysLog) 
    } 
    log.Println("LOG_INFO + LOG_LOCAL7: Logging in Go!") 

After the call to syslog.New(), you will have to check the error variable that is returned from it so that you can make sure that everything is fine. If everything is OK, which means that the value of the error variable is equal to nil, you call the log.SetOutput() function, which sets the output destination of the default logger, which, in this case, is the logger you created earlier on (sysLog). Then, you can use log.Println() to send information to the log server.

The third part of logFiles.go comes with the following code:

    sysLog, err = syslog.New(syslog.LOG_MAIL, "Some program!") 
    if err != nil { 
        log.Fatal(err) 
    } else { 
        log.SetOutput(sysLog) 
    } 
 
    log.Println("LOG_MAIL: Logging in Go!") 
    fmt.Println("Will you see this?") 
} 

The last part shows that you can change the logging configuration in your programs as many times as you want and that you can still use fmt.Println() for printing output on the screen.

The execution of logFiles.go will create the following output on the screen of a Debian Linux machine:

$ go run logFiles.go
    
Broadcast message from systemd-journald@mail (Tue 2017-10-17 20:06:08 EEST):
    
logFiles[23688]: Some program![23688]: 2017/10/17 20:06:08 LOG_MAIL: Logging in Go!
    
    
Message from syslogd@mail at Oct 17 20:06:08 ...
Some program![23688]: 2017/10/17 20:06:08 LOG_MAIL: Logging in Go!
Will you see this?
  

Executing the same Go code on a macOS High Sierra machine generated the following output:

$ go run logFiles.go
Will you see this?
  

Please bear in mind that most UNIX machines store logging information in more than one log file, which is also the case with the Debian Linux machine used in this section. As a result, logFiles.go sends its output to multiple log files, which can be verified by the output of the following shell commands:

$ grep LOG_MAIL /var/log/mail.log
Oct 17 20:06:08 mail Some program![23688]: 2017/10/17 20:06:08 LOG_MAIL: Logging in Go!
$ grep LOG_LOCAL7 /var/log/cisco.log
Oct 17 20:06:08 mail logFiles[23688]: 2017/10/17 20:06:08 LOG_INFO + LOG_LOCAL7: Logging in Go!
$ grep LOG_ /var/log/syslog
Oct 17 20:06:08 mail logFiles[23688]: 2017/10/17 20:06:08 LOG_INFO + LOG_LOCAL7: Logging in Go!
Oct 17 20:06:08 mail Some program![23688]: 2017/10/17 20:06:08 LOG_MAIL: Logging in Go!
  

The preceding output shows that the message of the log.Println("LOG_INFO + LOG_LOCAL7: Logging in Go!") statement was written on both /var/log/cisco.log and /var/log/syslog, whereas the message of the log.Println("LOG_MAIL: Logging in Go!") statement was written on both /var/log/syslog and /var/log/mail.log.

The important thing to remember from this section is that if the logging server of a UNIX machine is not configured to catch all logging facilities, some of the log entries you send to it might get discarded without any warnings.

About log.Fatal()

In this section, you will see the log.Fatal() function in action. The log.Fatal() function is used when something really bad has happened and you just want to exit your program as fast as possible after reporting the bad situation.

The use of log.Fatal() is illustrated in the logFatal.go program, which contains the following Go code:

package main 
 
import ( 
    "fmt" 
    "log" 
    "log/syslog" 
) 
 
func main() { 
    sysLog, err := syslog.New(syslog.LOG_ALERT|syslog.LOG_MAIL, "Some program!") 
    if err != nil { 
        log.Fatal(err) 
    } else { 
        log.SetOutput(sysLog) 
    } 
 
    log.Fatal(sysLog) 
    fmt.Println("Will you see this?") 
} 

Executing log.Fatal() will create the following output:

$ go run logFatal.go
exit status 1
  

As you can easily understand, the use of log.Fatal() terminates a Go program at the point where log.Fatal() was called, which is the reason that you did not see the output from the fmt.Println("Will you see this?") statement.

However, because of the parameters of the syslog.New() call, a log entry has been added to the log file that is related to mail, which is /var/log/mail.log:

$ grep "Some program" /var/log/mail.log
Jan 10 21:29:34 iMac Some program![7123]: 2019/01/10 21:29:34 &{17 Some program! iMac.local   {0 0} 0xc00000c220}
  

About log.Panic()

There are situations where a program will fail for good and you want to have as much information about the failure as possible.

In such difficult times, you might consider using log.Panic(), which is the logging function that is illustrated in this section using the Go code of logPanic.go.

The Go code of logPanic.go is as follows:

package main 
 
import ( 
    "fmt" 
    "log" 
    "log/syslog" 
) 
 
func main() { 
    sysLog, err := syslog.New(syslog.LOG_ALERT|syslog.LOG_MAIL, "Some program!") 
    if err != nil { 
        log.Fatal(err) 
    } else { 
        log.SetOutput(sysLog) 
    } 
 
    log.Panic(sysLog) 
    fmt.Println("Will you see this?") 
} 

Executing logPanic.go on macOS Mojave will produce the following output:

$ go run logPanic.go
panic: &{17 Some program! iMac.local   {0 0} 0xc0000b21e0}
    
goroutine 1 [running]:
log.Panic(0xc00004ef68, 0x1, 0x1)
    /usr/local/Cellar/go/1.11.4/libexec/src/log/log.go:326 +0xc0
main.main()
    /Users/mtsouk/Desktop/mGo2nd/Mastering-Go-Second-Edition/ch01/logPanic.go:17 +0xd6
exit status 2
  

Running the same program on a Debian Linux with Go version 1.3.3 will generate the following output:

$ go run logPanic.go
panic: &{17 Some program! mail   {0 0} 0xc2080400e0}
    
goroutine 16 [running]:
runtime.panic(0x4ec360, 0xc208000320)
    /usr/lib/go/src/pkg/runtime/panic.c:279 +0xf5
log.Panic(0xc208055f20, 0x1, 0x1)
    /usr/lib/go/src/pkg/log/log.go:307 +0xb6
main.main()
    /home/mtsouk/Desktop/masterGo/ch/ch1/code/logPanic.go:17 +0x169
    
goroutine 17 [runnable]:
runtime.MHeap_Scavenger()
    /usr/lib/go/src/pkg/runtime/mheap.c:507
runtime.goexit()
    /usr/lib/go/src/pkg/runtime/proc.c:1445
    
goroutine 18 [runnable]:
bgsweep()
    /usr/lib/go/src/pkg/runtime/mgc0.c:1976
runtime.goexit()
    /usr/lib/go/src/pkg/runtime/proc.c:1445
    
goroutine 19 [runnable]:
runfinq()
    /usr/lib/go/src/pkg/runtime/mgc0.c:2606
runtime.goexit()
    /usr/lib/go/src/pkg/runtime/proc.c:1445
exit status 2
  

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

Analogous to the log.Fatal() function, the use of the log.Panic() function will add an entry to the proper log file and will immediately terminate the Go program.

Writing to a custom log file

Sometimes, you just need to write your logging data in a file of your choice. This can happen for many reasons, including writing debugging data, which sometimes can be too much, without messing with the system log files, keeping your own logging data separate from system logs in order to transfer it or store it in a database, and storing your data using a different format. This subsection will teach you how to write to a custom log file.

The name of the Go utility will be customLog.go, and the log file used will be /tmp/mGo.log.

The Go code of customLog.go will be presented in three parts. The first part is as follows:

package main 
 
import ( 
    "fmt" 
    "log" 
    "os" 
) 
 
var LOGFILE = "/tmp/mGo.log" 

The path of the log file is hardcoded into customLog.go using a global variable named LOGFILE. For the purposes of this chapter, that log file resides inside the /tmp directory, which is not the usual place for storing data because usually, the /tmp directory is emptied after each system reboot. However, at this point, this will save you from having to execute customLog.go with root privileges and from putting unnecessary files into system directories. If you ever decide to use the code of customLog.go in a real application, you should change that path into something more rational.

The second part of customLog.go is as follows:

func main() { 
    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() 

Here, you create a new log file using os.OpenFile() using the desired UNIX file permissions (0644).

The last part of customLog.go is the following:

    iLog := log.New(f, "customLogLineNumber ", log.LstdFlags) 
 
    iLog.SetFlags(log.LstdFlags) 
    iLog.Println("Hello there!") 
    iLog.Println("Another log entry!") 
} 

If you look at the documentation page of the log package, which, among other places, can be found at https://golang.org/pkg/log/, you will see that the SetFlags function allows you to set the output flags (options) for the current logger. The default values as defined by LstdFlags are Ldate and Ltime, which means that you will get the current date and the time in each log entry you write in your log file.

Executing customLog.go will generate no visible output. However, after executing it twice, the contents of /tmp/mGo.log will be as follows:

$ go run customLog.go
$ cat /tmp/mGo.log
customLog 2019/01/10 18:16:09 Hello there!
customLog 2019/01/10 18:16:09 Another log entry!
$ go run customLog.go
$ cat /tmp/mGo.log
customLog 2019/01/10 18:16:09 Hello there!
customLog 2019/01/10 18:16:09 Another log entry!
customLog 2019/01/10 18:16:17 Hello there!
customLog 2019/01/10 18:16:17 Another log entry!
  

Printing line numbers in log entries

In this section, you are going to learn how to print the line number of the source file that executed the statement that wrote the log entry to a log file using the Go code of customLogLineNumber.go. This will be presented in two parts. The first part is as follows:

package main 
 
import ( 
    "fmt" 
    "log" 
    "os" 
) 
 
var LOGFILE = "/tmp/mGo.log" 
 
func main() { 
    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() 

So far, there is nothing special when compared to the code of customLog.go.

The remaining Go code of customLogLineNumber.go is as follows:

    iLog := log.New(f, "customLogLineNumber ", log.LstdFlags) 
    iLog.SetFlags(log.LstdFlags | log.Lshortfile) 
    iLog.Println("Hello there!") 
    iLog.Println("Another log entry!") 
} 

All the magic happens with the iLog.SetFlags(log.LstdFlags | log.Lshortfile) statement, which, apart from log.LstdFlags, also includes log.Lshortfile. The latter flag adds the full filename as well as the line number of the Go statement that printed the log entry in the log entry itself.

Executing customLogLineNumber.go will generate no visible output. However, after two executions of customLogLineNumber.go, the contents of the /tmp/mGo.log log file will be similar to the following:

$ go run customLogLineNumber.go
$ cat /tmp/mGo.log
customLogLineNumber 2019/01/10 18:25:14 customLogLineNumber.go:26: Hello there!
customLogLineNumber 2019/01/10 18:25:14 customLogLineNumber.go:27: Another log entry!
$ go run customLogLineNumber.go
$ cat /tmp/mGo.log
customLogLineNumber 2019/01/10 18:25:14 customLogLineNumber.go:26: Hello there!
customLogLineNumber 2019/01/10 18:25:14 customLogLineNumber.go:27: Another log entry!
customLogLineNumber 2019/01/10 18:25:23 customLogLineNumber.go:26: Hello there!
customLogLineNumber 2019/01/10 18:25:23 customLogLineNumber.go:27: Another log entry!
  

As you can see, using long names for your command-line utilities makes your log files difficult to read.

In Chapter 2, Understanding Go Internals, you will learn how to use the defer keyword for printing the log messages of a Go function more elegantly.