How Logging slowed down my Application

image from smallbiztrends

Tech Stack

Golang with gin framework and logrus

Context

(nah not golang context, Project context)

I was working for a fintech project with aim of building a scalable and performant Digital Platform mainly for typical banking services. The most important aspect of logs was getting revisited and we had an audit requirement to sanitize our logs by masking important information like pan card number, account number,etc.

Sounds easy right?

Trust your developers to mask it when they log it!

Sounds easy phew. But what about the new joinee who joined project 2 days back. Of-course we are developers not machines, so how do we avoid accidental misses.

Ain’t there any generic solution for this?

Solution:

Since we were using logrus, I tumbled across hooks for a generic way of handling the masking.

In logrus, hooks provide a centralized way of intercepting the log message. So before the log message hits the Filesystem, we have a handle to manipulate the message.

I will give a sample example of masking last 6 digits of a 10 digit account number. So we built this beautiful regular expression to catch any account number inadvertently being dumped into logs without masking.

import (
   "github.com/sirupsen/logrus"
   "regexp"
)
type AccountNumberMasker struct {
   *regexp.Regexp
}

func (AccountNumberMasker) Levels() []logrus.Level {
   return logrus.AllLevels
}
func (hook AccountNumberMasker) Fire(l *logrus.Entry) error {
   l.Message = hook.ReplaceAllString(l.Message, "$1******$2")
   l.Message = hook.ReplaceAllString(l.Message, "$1******$2")
   return nil
}

func NewAccountNumberMasker() AccountNumberMasker {
   return AccountNumberMasker{
regexp.MustCompile(`(\D|^)\d{4}(\d{6}(?:\D|$))`)
}
}

Days Passed

All was going good, until our monitoring radars picked up performance issues with certain api’s.

Logging code snippet would be the last ones to get investigated during performance crisis

I would keep the contents of debugging and finding the needle of the haystack for some other time. For experts, I had used pprof to pinpoint the root cause.

Root cause

There were some log messages especially request body and response body logging which turned out to be too large text. And our regex was taking too long to replace the text thus taking a lot of time to write log.

Interestingly golang does not support lookahead as it uses RE2 unlike java based regex engine PCRE. And hence you see 2 replaces in the above code snippet.

Regex as a topic is an ocean which needs a background. Here are some good reads, if you want to understand more on how regexes are implemented across different languages. Time complexities and scenarios when one outperforms others.

So be careful when you use regex to match and replace strings. Be wary and do proper analysis on your the size of text in which you are applying regex.

https://swtch.com/~rsc/regexp/

A comparison of regex engines

Regular expression