Below are some of the interesting bugs that I encountered over the course of my software engineering career.

Increasing Number of Repeated Logs – Sept 2017

When I was writing a new service in our Rails server to talk to another service, something strange happened. I noticed that the same log for requests sent by the service were getting printed to the console repeatedly for more than 10 times. And as time goes by, the number of repeated logs seems to be increasing.

When I first tried to approach the issue, I thought, “Maybe I didn’t follow the correct format as the other services?”

So I changed my new service structure to be exactly the same as the other services and tried sending request again. The log still appear multiple times. Maybe the hot reloading is not working? So I restarted the server and tried again. This time, the issue disappeared. “Great!”, I thought the issue was fixed.

However, a few hours later, it started happening again. Now it is printing duplicate logs 4 times, less than the initial 10 times, but still not solved.

Could it be due to multiple rails consoles that I opened? I restarted the server, tried sending request, opening another console, sending again, the log is only printed once.

Then when I moved on to write some code and come back to check the log a few hours later, it is getting printed multiple times again.

I decided to do some logging using ruby puts method in the code to check where the multiple log printing originates from. After adding logging and restarting the server, I once again moved on to other things.

As expected, I see 2 repeated logs printed, but the code that calls the logger was only called once, so it must be a problem of the subscriber.

The moment of truth came when I removed my puts from the code. After sending a request, I see 3 repeated logs, one more than the original.

Following this, I tried undoing the removal of puts, and (un)surprisingly, now there are 4 repeated logs.

So it is the editing of the file that caused the log to be printed repeatedly? Then I came to the realization that it must be the hot reload. Something during the hot reload triggered the subscriber to re-subscribe.

Indeed, after inspecting the service, I noticed that the code to subscribe to logging event was outside the service class. So it is getting executed every time when the hot reload is being carried out.

Case closed.