Logging

Logging is also pretty important part of most web applications because we usually want to know what requests are coming in, and what's more important, whether there are any unexpected errors. So, as you may have guessed, this section will introduce logging and i will show you how to setup logging, and how to separate logging in dev and prod environments. Now we will use -env flag added in previous section.

For logging we will use zerolog module, which you can get by running go get github.com/rs/zerolog/log.

Now let's create another directory internal/logging/ and file logging.go inside of it:

package logging

import (
  "fmt"
  "io"
  "io/ioutil"
  "os"
  "path/filepath"
  "strings"
  "time"

  "github.com/gin-gonic/gin"
  "github.com/rs/zerolog"
  "github.com/rs/zerolog/log"
)

const (
  logsDir = "logs"
  logName = "gin_production.log"
)

var logFilePath = filepath.Join(logsDir, logName)

func SetGinLogToFile() {
  gin.SetMode(gin.ReleaseMode)
  logFile, err := os.Create(logFilePath)
  if err != nil {
    log.Panic().Err(err).Msg("Error opening Gin log file")
  }
  gin.DefaultWriter = io.MultiWriter(logFile)
}

func ConfigureLogger(env string) {
  zerolog.SetGlobalLevel(zerolog.DebugLevel)
  switch env {
  case "dev":
    stdOutWriter := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: "15:04:05.000"}
    logger := zerolog.New(stdOutWriter).With().Timestamp().Logger()
    log.Logger = logger
  case "prod":
    createLogDir()
    backupLastLog()
    logFile := openLogFile()
    logFileWriter := zerolog.ConsoleWriter{Out: logFile, NoColor: true, TimeFormat: "15:04:05.000"}
    logger := zerolog.New(logFileWriter).With().Timestamp().Logger()
    log.Logger = logger
  default:
    fmt.Printf("Env not valid: %s\n", env)
    os.Exit(2)
  }
}

func createLogDir() {
  if err := os.Mkdir(logsDir, 0744); err != nil && !os.IsExist(err) {
    log.Fatal().Err(err).Msg("Unable to create logs directory.")
  }
}

func backupLastLog() {
  timeStamp := time.Now().Format("20060201_15_04_05")
  base := strings.TrimSuffix(logName, filepath.Ext(logName))
  bkpLogName := base + "_" + timeStamp + "." + filepath.Ext(logName)
  bkpLogPath := filepath.Join(logsDir, bkpLogName)

  logFile, err := ioutil.ReadFile(logFilePath)
  if err != nil {
    if os.IsNotExist(err) {
      return
    }
    log.Panic().Err(err).Msg("Error reading log file for backup")
  }

  if err = ioutil.WriteFile(bkpLogPath, logFile, 0644); err != nil {
    log.Panic().Err(err).Msg("Error writing backup log file")
  }
}

func openLogFile() *os.File {
  logFile, err := os.OpenFile(logFilePath, os.O_WRONLY|os.O_CREATE, 0644)
  if err != nil {
    log.Panic().Err(err).Msg("Error while opening log file")
  }
  return logFile
}

func curentDir() string {
  path, err := os.Executable()
  if err != nil {
    log.Panic().Err(err).Msg("Can't get current directory.")
  }
  return filepath.Dir(path)
}

And then we can update internal/cli/cli.go to configure logging based on environment instead of just printing it:

package cli

import (
  "flag"
  "fmt"
  "os"

  "rgb/internal/logging"
)

func usage() {
  fmt.Print(`This program runs RGB backend server.

Usage:

rgb [arguments]

Supported arguments:

`)
  flag.PrintDefaults()
  os.Exit(1)
}

func Parse() {
  flag.Usage = usage
  env := flag.String("env", "dev", `Sets run environment. Possible values are "dev" and "prod"`)
  flag.Parse()
  logging.ConfigureLogger(*env)
  if *env == "prod" {
    logging.SetGinLogToFile()
  }
}

This seems like a lot of code, but it's quite simple. First we configure our logger based on environment. If env is dev we will log everything to stdout, while for prod environment we will log into file. When logging into file we will first create logs directory if needed and backup previous log, so we have fresh log for every server start. Of course, you can create different logic for log rotation which better suits your needs. Another thing we need to do in this case is to tell Gin to run in release mode, which will reduce unnecessary and noisy output, and then also set default Gin writer to write into log file. You can also do that inside of a prod case block, but since we actually have 2 different loggers (Gin's attached logger and our zerolog logger) i like to separate those 2 parts of code. It's just a personal preference and you can do it your way. With this set we can now start logging some errors. For example, let's update logAndPanic() function inside internal/conf/conf.go:

func logAndPanic(envVar string) {
  log.Panic().Str("envVar", envVar).Msg("ENV variable not set or value not valid")
}

We can also log if error happens while generating password salt inside of internal/store/users.go:

func GenerateSalt() ([]byte, error) {
  salt := make([]byte, 16)
  if _, err := rand.Read(salt); err != nil {
    log.Error().Err(err).Msg("Unable to create salt")
    return nil, err
  }
  return salt, nil
}

It's entirely up to you to log whatever you want. So feel free to update code with logging of your choice or check out RGB GitHub repo to see how i did it. Let's now move on to the next section.