Logging is an essential component of developing applications. It helps in many ways, but still many developers being overconfident about their code never add proper logging to their applications.
It is not a difficult task, I think it is one of the most easiest thing that developers can do to make their code more reliable and easy to debug. There are many frameworks that can be used, most of which are extremely simple. Sometimes developers add these framework to their projects, but they seldom use them properly.
For example, what will you do if you see a log message that says:
We can not submit your request.
Apart from knowing something failed, what help can anyone get from this? Nothing at all. This message is logged as a custom message and it could have been a little more verbose.
Another form of message is this,
Object reference not set to an instance of object.
Now you know exactly which error happened, but again, can you do anything about this? Little stack trace info would have been awesome. This message is of no use without information about error source location.
Many times we validate our data transfer objects for data validity. You submit something from client to service and request fails due to invalid data. Most of the time you will see a message like this:
Request failed due to validation issue. ID – 1. Followed by stack trace and error location.
Now this message is definitely more helpful, but still we can have more information here like which validation failed and what was the data value for which validation failed.
Most of the applications follow layered architecture which means they will have a data layer, business layer and UI. Business layer most of the time is implemented via services. In this architecture, you will usually have 2 log files. One for UI and other one for service. Now, suppose error happened and you go to UI log file and see this:
UI – Log. Service failed to process this request. Please contact administrator.
Now, you open service log and see more than one error messages. Huh…how will you now relate UI error message with service error message. If your app is used by few people, only few times a day, you can use log message time stamps to relate these errors. Most of the time this will not work and you will have multiple log message with almost similar time stamp. One way to easily solve this is by generating a correlation Id (Guid), logging that with error message in service log and then pass that same correlation Id as part of service fault. Log the UI error message with same correlation ID and you are done. So you will see something like this in UI log file;
(ID: 1234-23322-34322….) Service failed to process this request. Please contact administrator.
and service log will have error logged like this;
(ID: 1234-23322-34322….) Invalid argument [User Name – Brad John]. Data not found in data store. Followed by stack trace.
Now you can use this pattern to show generic error message with correlation ID on user interface and then ask user to pass that correlation ID to your admin/ support team. They can easily get to the real problem.
At a high level, you should do this for logging:
- don’t shy away from logging verbose errors
- don’t just log error message (ex.Message)
- don’t forget to add stack trace information
- use throw in place of throw ex. If throwing new exception, then add old exception as inner exception. This will preserve stack trace information.
- provide extensive information that can be used for debugging
- log exactly due to which data value a business validation failed
- log informational messages that can be easily turned off via configuration
- use correlation pattern to relate error message logs in different app layers
These are few things which I’ve on top of my head. Over the years I’ve used multiple logging frameworks with each one having their own pros and cons. In next few posts I’ll discuss these frameworks and thier usage.