I have been working with Golang Lambdas for around 6 months now and one of the main problems, we have encountered over the development lifecycle is reporting and observability.
Lambdas do not run constantly like code on traditional servers. Instead they are only spun up when needed and kept “warm” until they are no longer needed and then spun down. To diagnose problems, it is important that we have plenty of information going into the logs such as unique run ids, and lots of information about which part of your code is getting run. So here are the top four things that I have learnt whilst working with go lambdas.
Use Logrus
Logrus is the defacto logging library for Golang, it implements the logger interface which comes as part of the go standard library. It can be best used to create formatted log entries. That is a log line, filled with meta data in an easily readable json format.
Setting up
To install with glide;
glide get github.com/sirupsen/logruselse
go get github.com/sirupsen/logrusBasic Usage
logger := logrus.New()
logger.SetFormatter(&logrus.JSONFormatter{}
logger.SetLevel(logrus.DebugLevel)
logger.WithFields(log.Fields{"animal": "walrus"}).Info("A walrus appears")Unique run id
Because you can have multiple instances of lambdas running at the same time, serving different requests it is important to make sure that each time you log, you log some kind of id that is unique to that request.
The best way I have found of doing this is generating a unique run id in the handle function and adding the run_id as an additional Logrus field. From here on out all logs for this request will have the same run id.
Giving you a clear path to how the request was processed.
TIP: make sure you generate the unique id in the handle function and not in the main. The main function is only called once, when the container is spun up. If the unique id is created here every request that this lambda will serve (until it is torn down, will have the same id)
func main () {
lambda.Start(handler)
}
func handler() {
logger := logrus.New()
logger.SetFormatter(&logrus.JSONFormatter{}
logger.SetLevel(logrus.DebugLevel)
// Generate run_id
runId := GenerateRunId() // RNdomRun1d
logger.WithFields(log.Fields{"run_id": runId})
run(logger)
}
func run(logger *logrus.Logger) {
logger.Info("Beginning...") // {run_id: "RNdomRun1d", msg: "Beginning..."}
// do some work
logger.Info("Halfway through...") // {run_id: "RNdomRun1d", msg: "Halfway through..."}
// do something else
logger.Info("I love observability!!") // {run_id: "RNdomRun1d", msg: "I love observability!!"}
}
func GenerateRunId() string {
rand.Seed(time.Now().UnixNano())
letterRunes := []rune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ")
b := make([]rune, 10)
for i := range b {
b[i] = letterRunes[rand.Intn(len(letterRunes))]
}
return string(b)
}When querying cloudwatch to see everything that has happened in the request simply search for;
{ $.run_id = "RNdomRun1d" }And you will get returned;
12:00:01 {run_id: "RNdomRun1d", msg: "Beginning..."}
12:00:01 {run_id: "RNdomRun1d", msg: "Halfway through..."}
12:00:01 {run_id: "RNdomRun1d", msg: "I love observability!!"}JSON Logging
When I wish to debug code my code or pull metrics out of my code I always use the json formatting. I do this because it is easily greppable by Cloudwatch. For anyone who doesn’t know how to query Cloudwatch more information can be found here in a previous blog post. The most important thing is to put as much useful information into the log as possible, whilst preventing any unwanted information from slipping in.
log := logrus.New()
log.SetFormatter(&logrus.JSONFormatter{})
log.ErrorUse levels
It can be tempting to litter your code with “info” levels but I recommend that you don’t. The most common levels I use are debug, info, and error. Once the code has been live for a few months and everything has settled down I then remove the debug logs quieting down even further.