Never go blind on
Production:
We all know Logging
for an application is important. I have seen few people asking me to disable
INFO logging in production. I believe that’s not fair since we see a pattern of
log in development or stage environment and see different logging in Production
if we disable the INFO logging.
So here is My
logging ethics to keep the logging minimum and efficient, easy for debugging
- Print the request and response headers and body. If the request body or response body is huge print only 2000 characters.
- Add logging for Entry event and Exit event of each api which is exposed through any protocol like SOAP, REST, and XML-RPC, etc
- In exit append time taken for execution.
- In entry and exit logging append the used memory( runtime.totalMemory() -runtime.freeMemory() ) andavailable memory( runtime.freeMemory())
- Add logging for Entry event and Exit event for Database layer
- In exit event append time taken for execution.
- Allocate minimum 100 GB for log folder.
- Have a background thread running to collect each entry and exit, and calculate the min, max, average of the events and print every 5 mins.
- In exception handling print the exception message and throw it to api entry layer and handle it. In specific few scenarios we might need to suppress the exception. Even in those cases print in INFO what’s the error and why we have suppressed it.
Sample Test Application Logging:
2016-02-17
06:46:46,771 INFO srinivasan-java [ajp-bio-8109-exec-16] 2740 * Server has
received a request:[ Live
Request Count : 1 ]:[ Heap
Memory Free : 1691 MB:: Heap Memory Max :1820 MB ]
2740 > GET https://srini.com/java
2740 >
accept: application/json, text/plain, */*
2740 >
accept-encoding: gzip, deflate
2740 >
accept-language: en-US,en;q=0.8
2740 >
connection: keep-alive
2740 > content-length: 2
2740 >
content-type: application/json;charset=UTF-8
2740 >
host: srinivasan-java
2740 >
remoteClientIP: 10.0.0.0
2740 >
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/48.0.2564.103 Safari/537.36
2016-01-17
06:46:46,771 INFO srinivasan-java [ajp-bio-8109-exec-16] Request Url : /java
2016-01-17
06:46:46,772 INFO srinivasan-java [ajp-bio-8109-exec-16] ENTERING: JavaDetails - Start
request processing
2016-01-17
06:46:46,775 INFO srinivasan-java [ajp-bio-8109-exec-16] ENTERING:
DAO_GetConfig - Start request processing
2016-01-17
06:46:46,779 INFO srinivasan-java [ajp-bio-8109-exec-16] Gauge Name :
APP.DAO_GetConfig_T : ElapsedTime : 4
2016-01-17
06:46:46,779 INFO srinivasan-java [ajp-bio-8109-exec-16] EXITING: DAO_GetConfig
- End request processing
2016-01-17
06:46:46,787 INFO srinivasan-java [ajp-bio-8109-exec-16] ENTERING: DAO_GetTalent
- Start request processing
2016-01-17
06:46:46,792 INFO srinivasan-java [ajp-bio-8109-exec-16] Gauge Name :
APP.DAO_GetTalent_T : ElapsedTime : 5
2016-01-17
06:46:46,792 INFO srinivasan-java [ajp-bio-8109-exec-16] EXITING: DAO_GetTalent
- End request processing
2016-01-17
06:46:46,792 INFO srinivasan-java [ajp-bio-8109-exec-16] Gauge Name :
APP.GetTalent_T : ElapsedTime : 20
2016-01-17
06:46:46,792 INFO srinivasan-java [ajp-bio-8109-exec-16] EXITING: JavaDetails - End
request processing
2016-01-17
06:46:46,792 INFO srinivasan-java [ajp-bio-8109-exec-16] TOTAL REQUEST TIME : 21
2016-02-17
06:46:46,793 INFO srinivasan-java [ajp-bio-8109-exec-16] 2740 * Server
responded with a response:[ Live Thread Count : 1 ]
2740 < 200
2740 < Content-Type: application/json
{"Talent":[{"TalentId":"001","TalentName":"AWS
Lab"}]}
<<Watch this space for code sample>>
