Better logging for GORM and configuring to work with Logrus

Jan 20, 2020
golang gorm

In a previous post - Go REST API with GORM and MySQL, we saw how to build a simple REST service in Golang with MySQL and the GORM framework for object-relational mapping. This is a quick post about how to enable logging in GORM and how we can tweak it to work with a structured, feature-rich logging framework like logrus.

Why logging?

An ORM makes it easier to work with an underlying relational database by provide a simple interface and avoiding the need to write SQL queries manually. As developers, we would often find ourselves in situations where we need to understand the queries being generated under the hood by the ORM. We could be debugging issues where our code is not fetching all the data we wanted or the operation may be taking an insanely large amount of time to complete.

In such cases, having some visibility into the actual query will go a long way in helping us debug functional and performance issues. (There have been so many times where the SQL query generated by the ORM is different from what I expected it to be). Once we have the query, a common path of action is to use explain to understand the query plan and try to optimize it.

Current state of logging in GORM

By default, Gorm only logs errors and nothing else. For example, if we try to create a database that exists already , we could see the following error message in the logs:

// Trying to create a database twice
db.Exec("CREATE DATABASE orders_db")
db.Exec("CREATE DATABASE orders_db")

In this default configuration, no logs are printed when the query gets executed successfully. In order to enable logging for all queries, we need to invoke the LogMode method with true as the argument.

// Enable Logger, show detailed log
db.LogMode(true)

The logs below are for a simple /GET API call which retrieves records from the orders and items table.

Setting LogMode as false does the opposite and does not display any log messages, even for errors - I can’t think of a reason why someone would use this though. (Unless they share some of Jeff Altwood’s views on logging).

// Disable Logger, don't show any log even errors
db.LogMode(false)

If we have disabled logging but would like to debug a specific operation/query, we can prepend the .Debug() method.

// Debug a single operation, show detailed log for this operation
db.Debug().Where("name = ?", "jinzhu").First(&User{})

By default, the logger also displays the query execution time, which is pretty useful if you are monitoring/debugging for performance.

What can we improve?

In my opinion, the GORM logger needs to be hooked with a different framework <> before we start using it for application in production. The following are some of the the limitations I could list from my experience:

1. Unstructured logging: makes it really hard to centralize/aggregate logs and enable search with tools like Splunk, Elastic Search, etc.

2. No timezone info: If we look at the log statements, the timestamp doesn’t have any timezone information - I think this is really essential information for logs, since our application could be deployed across multiple data-centers spanning different timezones, and timezone information is absolutley

3. Common Log Schema: Sometimes, we may have a common log schema used throughout the application, and would prefer that GORM logs adhere to the same schema/format as well for consistent logging across the application.

Additionally, hooking up with Logrus would let us define custom log formatters and leverage logrus hooks as well. For example, you can easily notify a slack channel on error via the Slackrus hook - All it takes is a couple of lines of code.

Define a custom logger

The below interface is defined in the logger.go file in the GORM code.

type logger interface {
    Print(v ...interface{})
}

In order to plug-in a different logger, all we need to do is to implement this interface and pass an instance of that implementing struct to the db.SetLogger() method. This is exactly what our GormLogger struct is for.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
// GormLogger struct
type GormLogger struct{}

// Print - Log Formatter
func (*GormLogger) Print(v ...interface{}) {
  switch v[0] {
  case "sql":
    log.WithFields(
      log.Fields{
        "module":        "gorm",
        "type":          "sql",
        "rows_returned": v[5],
        "src":           v[1],
        "values":        v[4],
        "duration":      v[2],
      },
    ).Info(v[3])
  case "log":
    log.WithFields(log.Fields{"module": "gorm", "type": "log"}).Print(v[2])
  }
}
 

Line 2 declares the struct, and line 5 implements the function Print on the struct using Go’s receiver syntax. If you aren’t very familiar with receivers in Go, I’m linking a couple of posts that give a good explanation on implementing interfaces and receivers.

Now let’s head back to our example. We can look at receiver functions as a way of specifying that a function belongs to a struct. In the definition, func (*GormLogger) Print(v ...interface{}), (*GormLogger) is the receiver, meaning that the Print method is defined on the GormLogger struct. This implies that the GormLogger struct implements the logger interface, which again means that we can pass an instance of the GormLogger struct to the setLogger method be used as the custom logger.

In our definition of the Print method, we are formatting the log statement using logrus’ WithFields method that results in logs structured as multiple key-value pairs (rather than a single long, unstructured log message).

Configure GORM to use a custom logger

Now that we have defined a custom logger, the following code snippet shows how to configure GORM to use it while initializing the DB connection.

func initDB() {
    var err error
    dataSourceName := "root:@tcp(localhost:3306)/?parseTime=True"
    db, err = gorm.Open("mysql", dataSourceName)

    if err != nil {
        fmt.Println(err)
        panic("failed to connect database")
    }

    db.SetLogger(&GormLogger{})
    // db.SetLogger(Sample{})
    db.LogMode(true)
    Formatter := new(log.TextFormatter)
    log.SetFormatter(Formatter)
    Formatter.FullTimestamp = true

    // Create the database. This is a one-time step.
    // Comment out if running multiple times - You may see an error otherwise
    db.Exec("CREATE DATABASE orders_db")
    db.Exec("USE orders_db")

    // Migration to create tables for Order and Item schema
    db.AutoMigrate(&Order{}, &Item{})
}

The below image is a snapshot of the logs with our custom logger/formatter.

Conclusion

In this post, we saw how to configure the GORM logger and how to customize it with a logging framework like logrus. You can checkout the complete code for this from Github. Please do comment below if you have any questions/issues with the code - I’ll be glad to help out.