Go daily log

brief introduction

In daily development, log is an essential function. Although sometimes we can use fmt library to output some information, but the flexibility is not enough. The Go standard library provides a log library. This paper introduces the use of log library.

Rapid use

log is provided by the Go standard library and does not need to be installed separately. Direct use:

package main

import (
  "log"
)

type User struct {
  Name string
  Age  int
}

func main() {
  u := User{
    Name: "dj",
    Age:  18,
  }

  log.Printf("%s login, age:%d", u.Name, u.Age)
  log.Panicf("Oh, system error when %s login", u.Name)
  log.Fatalf("Danger! hacker %s login", u.Name)
}

Log is output to stderr by default. The date and time will be automatically added before each log. If the log does not end with a line break, the log automatically adds a line break. That is, each log will be output in a new line.

log provides three sets of functions:

Print/Printf/Println: normal output log;
Panic/Panicf/Panicln: after outputting the log, call panic with the assembled string as the parameter;
Fatal / fatalf / fataln: after outputting the log, call os.Exit(1) to exit the program.

Naming is easy to distinguish. Those with f suffix have formatting function. Those with ln suffix will add a line break after the log.

Note that in the above program, log.Fatalf will not be called because calling log.Panicf will panic.

Customized

prefix

Call log.SetPrefix to prefix each log text. For example, set the Login: prefix in the above program:

package main

import (
  "log"
)

type User struct {
  Name string
  Age  int
}

func main() {
  u := User{
    Name: "dj",
    Age:  18,
  }

  log.SetPrefix("Login: ")
  log.Printf("%s login, age:%d", u.Name, u.Age)
}

Call log.Prefix to get the prefix of the current setting.

option

Set options to add additional information, such as date, time, filename, etc., to each output text.

The log library provides six options:

// src/log/log.go
const (
  Ldate         = 1 << iota
  Ltime                    
  Lmicroseconds            
  Llongfile                
  Lshortfile               
  LUTC                     
)

Ldate: output the date of the local time zone, such as 2020 / 02 / 07;
Ltime: output the time of the local time zone, such as 11:45:45;
Lmicroseconds: the output time is accurate to microseconds. If you set this option, you do not need to set Ltime. For example, 11:45:45.123123;
Long file: output the line number of the long file name, including the package name, such as github.com/darjun/go-daily-lib/log/flag/main.go:50;
Lshortfile: output the line number of the short file name, excluding the package name, such as main.go:50;
LUTC: if Ldate or Ltime is set, UTC time will be output instead of local time zone.

Call the log.SetFlag setting option to set more than one at a time:

package main

import (
  "log"
)

type User struct {
  Name string
  Age  int
}

func main() {
  u := User{
    Name: "dj",
    Age:  18,
  }

  log.SetFlags(log.Lshortfile | log.Ldate | log.Lmicroseconds)

  log.Printf("%s login, age:%d", u.Name, u.Age)
}

Call log.Flags() to get the currently set options.

Run code, output:

2020/02/07 11:56:59.061615 main.go:20: dj login, age:18

Note that after calling log.SetFlag, the original options will be overwritten!

The log library also defines an Lstdflag, which is Ldate | Ltime, which is our default option.

// src/log/log.go
const (
  LstdFlags = Ldate | Ltime
)

That's why by default, each log is automatically preceded by a date and time.

custom

In fact, the log library defines a default Logger for us, named std, which means standard log. We directly call the method of the log library, which internally calls the corresponding method of std:

// src/log/log.go
var std = New(os.Stderr, "", LstdFlags)

func Printf(format string, v ...interface{}) {
  std.Output(2, fmt.Sprintf(format, v...))
}

func Fatalf(format string, v ...interface{}) {
  std.Output(2, fmt.Sprintf(format, v...))
  os.Exit(1)
}

func Panicf(format string, v ...interface{}) {
  s := fmt.Sprintf(format, v...)
  std.Output(2, s)
  panic(s)
}

Of course, we can also define our own Logger:

package main

import (
  "bytes"
  "fmt"
  "log"
)

type User struct {
  Name string
  Age  int
}

func main() {
  u := User{
    Name: "dj",
    Age:  18,
  }

  buf := &bytes.Buffer{}
  logger := log.New(buf, "", log.Lshortfile|log.LstdFlags)

  logger.Printf("%s login, age:%d", u.Name, u.Age)

  fmt.Print(buf.String())
}

log.New accepts three parameters:

io.Writer: all logs will be written to this writer;
Prefix: prefix. You can also call logger.SetPrefix later;
flag: option. You can also call logger.SetFlag later.

The above code outputs the log to a bytes.Buffer, and then prints the buf fer to standard output.

Run code:

$ go run main.go 
2020/02/07 13:48:54 main.go:23: dj login, age:18

Note that the first parameter is io.Writer. We can use io.MultiWriter to achieve multi destination output. Next, we output the log to standard output, bytes.Buffer and file at the same time:

package main

import (
  "bytes"
  "io"
  "log"
  "os"
)

type User struct {
  Name string
  Age  int
}

func main() {
  u := User{
    Name: "dj",
    Age:  18,
  }

  writer1 := &bytes.Buffer{}
  writer2 := os.Stdout
  writer3, err := os.OpenFile("log.txt", os.O_WRONLY|os.O_CREATE, 0755)
  if err != nil {
    log.Fatalf("create file log.txt failed: %v", err)
  }

  logger := log.New(io.MultiWriter(writer1, writer2, writer3), "", log.Lshortfile|log.LstdFlags)
  logger.Printf("%s login, age:%d", u.Name, u.Age)
}

You can also send it to the network if you like.

Realization

The core of the log library is the Output method. Let's take a look at it briefly:

// src/log/log.go
func (l *Logger) Output(calldepth int, s string) error {
  now := time.Now() // get this early.
  var file string
  var line int
  l.mu.Lock()
  defer l.mu.Unlock()
  if l.flag&(Lshortfile|Llongfile) != 0 {
    // Release lock while getting caller info - it's expensive.
    l.mu.Unlock()
    var ok bool
    _, file, line, ok = runtime.Caller(calldepth)
    if !ok {
      file = "???"
      line = 0
    }
    l.mu.Lock()
  }
  l.buf = l.buf[:0]
  l.formatHeader(&l.buf, now, file, line)
  l.buf = append(l.buf, s...)
  if len(s) == 0 || s[len(s)-1] != '\n' {
    l.buf = append(l.buf, '\n')
  }
  _, err := l.out.Write(l.buf)
  return err
}

If the Lshortfile or lllongfile is set, the runtime.Caller is called in the Ouput method to get the file name and line number. The calldepth parameter of runtime.Caller indicates how many layers of the call stack are up. The current layer is 0.

The general call path is:

Functions such as log.Printf are used in the program;
Call std.Output in log.Printf.

We need to get the file and line number of the call log.printf in the output method. The calldepth import 0 represents the line information that calls the runtime.Caller in the Output method. The incoming 1 indicates the information that calls the row of std.Output in log.Printf, and passes in 2 to indicate the line information calling log.Printf in the program. Obviously we're going to use two here.

Then formatHeader is called to process prefixes and options.

Finally, the generated byte stream is written to the Writer.

Here are two optimization techniques:

Because the runtime.Caller call is time-consuming, release the lock first to avoid too long waiting time;
To avoid frequent memory allocation, a buf of type [] byte is saved in the logger, which can be reused. The prefix and log contents are written to this buf first, and then to the Writer in a unified way to reduce io operations.

summary

Log implements a small log library, which can be used easily. This article introduced its basic use, simply analyzed the source code. If the function of the log library can not meet the requirements, we can do secondary encapsulation on it. Look at fried fish This article.

In addition, the community has also emerged a lot of excellent and functional log libraries, which can be selected.