The Art of logging
When you have issues in production environment, application logs are the most useful assets to perform investigations and root cause analysis. In order to get the most value from your logs, it's important to follow some best practices when producing logs.
Learn how to write meaningful log messages that will help you to debug and solve issues in production
Log events using key/pair values
You should consider your application logs as a database of events that you'll query for investigating production issues. So instead of recording an event like this:
2020-11-11 15:00:00 Sending email to customers. 34 email sent, 3 failed
record it using the following format:
Date='2020-11-11 15:00:00' Action=Email SentEmails=4 FailedEmails=3
This format is more suitable for searches, you can easily filter events by
What to record in your logs?
Here is an example to HTTP calls to a web-service that recommends Stories to readers.
Here is the associate log record:
2020-11-11 13:52:12 Type=INFO HttpRequestMethod=GET HttpRequestType=application/json HttpRequestURI=/v1/story/recommend HttpResponseStatus=200 Latency=104 Limit=9 Recommendation="284 232 117 113 386 360 380 325 382 370 376 369 379" RecommendationAlgorithm=CategoryRecommendation StoryId=277 Success=true X-Message-ID=d22b1310-d87b-48e8-b8a3c2f9ab659108 X-Correlation-ID=4a069cd9-7442-460f-bfed-b9e24efaa1d8 X-Client-ID=myapp-android
This log record helps us to answer the following questions
When did the event occured?
Each log record should have a timestamp, normalized to UTC timezone. It helps understanding the sequence of events.
Who initiates the call?
These information help understanding the origin of the request. This includes:
- The HTTP Referer.
- The client's device information. Ex: User-Agent or phone's device ID
- The 3rd party caller (application or service). Ex: See
X-Client-IDin our example above, than indicate the call was initiated by the Android app.
What are the input?
These information help understanding the data sent to initiate the request. The input recorded should include:
- The URL called. Ex:
- The parameters. Ex:
POSTmethods, include the request body data serialized to key/pair values
What's the output?
There information help understanding what was returned to the caller. The output recorded should includes:
- HTTP status code to help understanding if the request was successful or not. Ex:
- The return value(s) of the call. Ex:
Recommendationcontaining the IDs of the stories recommended
Why that decision was made?
Add any intermediary information to help understanding how the system behaved, this is very useful for finding bugs. In our exemple,
RecomendationAlgorithm indicates which algorithm was used to perform the recommendation
Was the it successful?
Having a boolean field like
Success help us to easily filter successful or unsuccessful events.
For unsuccessful events, you should also record the reason why the failure occured:
- The error code
- The description of the failure
- The exception class name exception
- The exception stack trace so that we can identify to source of the error in the source code.
Here an example of log record on failure:
2020-11-11 13:52:12 Type=INFO ErrorCode=story_not_found ErrorMessage="The Story 315 was not wound" ExceptionClass=com.x.y.NotFoundException HttpRequestMethod=GET HttpRequestURI=/v1/story/recommend HttpResponseStatus=404 Latency=5 Limit=9 StoryId=277 Success=false X-Message-ID=d22b1310-d87b-48e8-b8a3c2f9ab659108 X-Correlation-ID=4a069cd9-7442-460f-bfed-b9e24efaa1d8 X-Client-ID=myapp-android Unexpected error 2020-11-11 13:52:12 com.x.y.NotFoundException: story_not_found 2020-11-11 13:52:12 at com.x.y.story.service.StoryService.findById(StoryService.kt:82) 2020-11-11 13:52:12 at at com.x.y.story.controller.StoryController.find()) ....
How long did it take?
Always add in your trace the latency of each operation. This will help you to identify bottleneck on your system. I usually record the latencies in milliseconds. Ex: See
Other Considerations for Logging
Use english language, because some tools or console have trouble printing certain unicode characters (Ex: accented characters)
As you record your log events using key/pair values, make sure to adopt the same naming convention for your fields: use either camel case (Ex:
UserId), snake case (Ex:
user_id) or kebab case (Ex:
Centralize your logs
Consider a centralized server where to aggregate all the the logs your applications. Using log aggregator like Splunk, Papertrail or Logstash will provide you additional query and monitoring capabilities.
Correlate log events
In the following exemple, a call from the mobile phone to the
ServiceA will initiate calls to
This will generate the following logs
service-a.log Date="Feb 05 12:33:16" ... X-Client-ID=myapp-android X-Correlation-ID=4a069cd9-7442-460f-bfed-b9e24efaa1d8 X-Message-ID=4a069cd9-7442-460f-bfed-11111111
service-b.log Date="Feb 05 12:34:00" ... X-Client-ID=service-a X-Correlation-ID=4a069cd9-7442-460f-bfed-b9e24efaa1d8 X-Message-ID=4a069cd9-7442-460f-bfed-22222222
service-c.log Date="Feb 05 12:34:10" ... X-Client-ID=service-a X-Correlation-ID=4a069cd9-7442-460f-bfed-b9e24efaa1d8 X-Message-ID=4a069cd9-7442-460f-bfed-22222222
- The field
X-Correlation-IDis used to group all the log events related to the same original call.
- The field
X-Message-IDis a globally unique identifier assigned to each log record
As always, it’s easier said than done. Logging requires some practice to master this, but once you have, you will know instinctively when and how you should log, and when you shouldn’t. As you perform investigations in production, refine and improve your logs to help your team in the future.