Better logging for GORM and configuring to work with Logrus
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.
|
|
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.
See Also
- Build a GraphQL API in Golang with MySQL and GORM using Gqlgen
- Build a REST API in Golang with MySQL, GORM and Gorilla Mux
- Consuming REST APIs in Go - HTTP GET, PUT, POST and DELETE