You're building an enterprise application. And it's a no brainer that there will be numbers of places where you would be having logs in the application.
Putting a lots of logs in the application gives you a some amount of performance hits. However, it is necessary to place logs at various places where some level of debugging is required. But, what if even placing a lots of logs in the application, you are still not able to debug the problem in the production??
Yeah, that would be a greatest technical sin. The Gods in the Cloud will not forgive you! (on the Cloud Server I mean :D ).
Consider you have a service named Invoice Service. This service has 2 instances running on the server.
This service has an endpoint to send invoice in email to a user. Consider it has following business logic.
What are your observations... Especially on the Logging??
public void emailInvoice(Long invoiceId, String emailTo) {
log.info("REST Call to email invoice {}", invoiceId);
try {
Invoice invoice = invoiceRepository.findById(invoiceId);
if (invoice != null) {
log.info("HEREEEE... Found invoice {}", invoice);
InvoiceRequestTracker invoiceRequestTracker = invoiceRequestTrackerRepository.findByInvoiceId(invoiceId);
if (invoiceRequestTracker.getRequestCount() < 5) {
emailService.sendEmail(invoice, emailTo);
log.info("Email sent successfully to {}", emailTo);
} else {
log.info("You cannot request and invoice more than 5 times!");
}
} else {
System.out.println("Oops.... Invoice not found!!");
}
} catch (Exception e) {
e.printStackTrace();
}
}
Well, my observations would be following:
- Forget logs, first of all, the code written very poorly in a dirty/non-readable fashion.
- Some loggers are not used with right LOG LEVEL.
- Some loggers have inappropriate variables printed, like whole entity object printed that will blow your performance to print such a huge object.
- Some loggers are not used with standard logging practice, such as sysout is used in place of logger methods.
- But the major problem is, THE CONTEXT IS MISSING FROM EACH LOGS!!
The problem
Observing each logs such as
log.info("REST Call to email invoice {}", invoiceId);
log.info("Email sent successfully to {}", emailTo);
log.info("You cannot request and invoice more than 5 times!");
System.out.println("Oops.... Invoice not found!!");
Such logs does not make any sense at all. Ask yourself a question.. You being a programmer, if you are asked to debug a simplest problem such as "Check whether an invoice with ID 24 is emailed to iam@hushensavani.com or not?", will you be able to debug the problem quickly with such logs has been put in the application?
You would argue,
YES.. why not!! I have logs like log.info("REST Call to email invoice {}", invoiceId); so I can find invoiceId from there and then I will check following logs such as, log.info("Email sent successfully to {}", emailTo); Hence, this will tell me whether the email is sent to this user with given email address for invoiceId printed in previous statement.
Whoa! such answer would be too naive to present.. isn't it!!
OK, consider there are concurrent requests coming for emailInvoice() from the multiple instances of this service running on a server. And you are checking logs in a common place like ELK where all the instances are logging the log events at one place at the same time.
Imagine what a mess you would create. Imagine how paranoid you will be when you start seeing concurrent logs from same method in a common place. Such as following.
2021-08-24 16:24:37.730 INFO REST Call to email invoice 24
2021-08-24 16:25:39.730 INFO REST Call to email invoice 369
..
..
2021-08-24 16:26:41.730 Email sent successfully to nikola@tesla.com
2021-08-24 16:26:42.730 Email sent successfully to iam@hushensavani.com
How would you figure out whether invoice number 24 is sent to nikola@tesla.com or to iam@hushensavani.com ??
Pretty messed up.. right??
Imagine, how damn you will misguide the person who has asked you to debug this problem!!
Okay!! So what's the Solution???
Solution is Logging with Context.
No matter how many statements are there in between two log statements, EACH AND EVERY LOG STATEMENT SHOULD HAVE THE CONTEXT!
The context is nothing but an indicator which tells that given log is the part of a given thread which is executing some X operation with given Y input performing Z task.
For example, Logs with Context would look like the following,
log.info("emailInvoice(): Invoice with ID {} is emailed successfully to {}", invoiceId, emailTo);
will print the logs like,
2021-08-24 16:25:33.730 emailInvoice(): Invoice with ID 369 is emailed successfully to nikola@tesla.com
Here, the context is InvoiceId which is mapped with outcome of sending email to a given email address or emailTo. Now it will be darn easy to debug code in one shot!
Consider the improvised logging code with context as following:
public void emailInvoice(Long invoiceId, String emailTo) {
log.info("emailInvoice(): REST call to email invoice with ID {} to email {}", invoiceId, emailTo);
try {
Invoice invoice = invoiceRepository.findById(invoiceId);
if (invoice == null) {
log.error("emailInvoice(): Invoice with ID {} is not found while sending email to {}", invoiceId, emailTo);
return;
}
log.info("emailInvoice(): Going to send email to {} for Invoice ID {}", emailTo, invoiceId);
InvoiceRequestTracker invoiceRequestTracker = invoiceRequestTrackerRepository.findByInvoiceId(invoiceId);
if (invoiceRequestTracker.getRequestCount() > applicationProperties.getEmailRequestThreshold()) {
log.error("emailInvoice(): Skipped sending email to {} for Invoice ID {} as request count is {} which is exceeded from threshold limit of {}", emailTo, invoiceId, invoiceRequestTracker.getRequestCount(), applicationProperties.getEmailRequestThreshold());
return;
}
emailService.sendEmail(invoice, emailTo);
log.info("emailInvoice(): Email is sent successfully to {} for Invoice ID {}", emailTo, invoiceId);
} catch (Exception e) {
log.error("emailInvoice(): Unable to send email to {} for Invoice ID {} due to error {}", emailTo, invoiceId, e.getMessage(), e);
}
}
Now the output would be like,
2021-08-24 16:24:37.730 INFO emailInvoice(): REST call to email invoice with ID 24 to email iam@hushensavani.com
2021-08-24 16:25:39.730 INFO REST call to email invoice with ID 369 to email nikola@tesla.com
..
..
2021-08-24 16:26:41.730 emailInvoice(): Email is sent successfully to nikola@tesla.com for Invoice ID 369
2021-08-24 16:26:42.730 emailInvoice(): Email is sent successfully to iam@hushensavani.com for Invoice ID 24
Now, it'll be pretty straight forward to debug the problem in a snap like a wizard!!
Hence, always maintain the context in each log statements in order to debug the problem effectively and save yourself from the embarrassment!!
It's a small practice to take care, but it will save you a big time!
Kindly share with your fellow developers and colleagues if you find this useful. Cheers!!