- Introduction
- Where to log
- Always add the IDs of the used data e.g. customerId, itemId…
- Not logging informations twice
- Consider all log levels
- No sensitive data in logs
Introduction
In my experience as a software engineer, I observed the lacking of logs in a lot oft software.
In this article I am going to show you how to write Logs that help you and your team.
Good logs lead to shorter debugging time, enabling SysOps/SREs from providing more usefull information on problems and you get the possibility to be alerted on certain logs.
If your Logs are bad or even missing, you lose all these advantages, making the maintaining and debugging of your software a lot harder than it needs to be.
For the examples we will take an imaginary web shop as I assume most of you can relate with the functionallity. The code is just pseudo code.
Where to log
1. Log on start and end of methods
To track start and end of longer methods add logs at the start and the end of the method.
function collectMoney() {
logger.info("Start collecting money from customer ${customer.id}")
...
logger.info("Finished collecting money from customer ${customer.id}")
}
2. Log if an error is happening
Log errors as soon as they come up. You need to react to them.
try {
order()
} catch(error) {
logger.error("An error occoured on ordering for customer ${customer.id} error: ${error}")
throw error
}
3. Log on steps in your business process
For readibility I didn’t add catches to each step, but on production systems you should add them to comprehend where the flow broke and why.
logger.info("Start shipping process for order ${order.id} of customer ${customer.id} with validation its shipping information")
validateShippingInformation()
logger.info("Validation of shipping information was successfull for order ${order.id} of customer ${customer.id}, continue with validation of item avaliability")
validateItemAvaliability()
...
notifyDispatcher()
logger.info("Finished successfully shipping process for order ${order.id} of customer ${customer.id}")
Hint: Don’t put these steps in numeric bullet points, you will forget to update them, if a step is added later on…
4. Log if behavior is controlled by configuration
if(config.emailNotification) {
logger.info("Notifications for delivery will be send via email")
//set email notification
} else if (config.smsNotification) {
logger.info("Notifications for delivery will be send via sms")
//set sms notification
} else {
logger.info("Notifications for delivery will not be send")
//dont notify at all
}
5. Tell where stuff is happening e.g. 3rd party system
Don’t do:
logger.info("Collecting amount ${amount} of money from customer ${customer.id}")
Instead do:
logger.info("Collecting amount ${amount} of money from customer ${customer.id} from PayPal")
6. Long running processes
On long running processes or a lot of loop iterations add a started and a finished log message
logger.info("Start with long running method")
longRunningMethod()
logger.info("Finished long running method") //optional log time needed
Always add the IDs of the used data e.g. customerId, itemId…
For example the customer adds an item to its card:
Don’t do:
logger.info("Customer ${customerId} adds an item to its card");
Instead add Ids:
logger.info("Customer ${customer.id} adds ${item.name} to its cart ${cart.id}");
Consider creating methods for standard log message format, like create a method that expects a customer id, optional an object id and object type and the log message itself.
Not logging informations twice
Avoid using the same log level directly one after another.
Don’t do:
logger.info("Start order process for customer ${customer.id}")
logger.info("Validate if all choosed items are available in cart ${cart.id} of customer ${customer.id}")
Instead do:
logger.info("Start order process with validating if all items in cart ${cart.id} of customer ${customer.id} are available")
Consider all log levels
Using the right log level is nothing generic, you have to decide on each log indivduelly which log level applies here correctly, but here are some tips.
1. Use warn
For example, we have a limit on how many items of a type can be bought per customer, but this customer has no value set, so the default limit is applied:
Don’t do:
logger.error("Customer ${customerId} has no shopping cart limit, will apply default shopping cart limit");
Instead use warn as the customer is not limited in doing something:
logger.warn("Customer ${customerId} has no shopping cart limit, will apply default shopping cart limit ${defaultLimits.shoppingCart}");
2. Don’t forget the debug log level
Some information is not so important that you need to see them the whole time, like request or response bodies or headers.
Example:
logger.log("Request PayPal to get money for customers ${customer.id} purchase ${purchase.id}");
logger.debug("Request send to PayPal for customer ${customer.id} and purchase ${purchase.id} payload: ${requestBody}");
No sensitive data in logs
Never log sensitive information!
If sensitive data is contained in an object that you want to log, build a function that hides the sensitive data.
If the sensitive data is invalid, for example a password that doesn’t meet the requirements, you can still log why the data is invalid.
Example:
Don’t do:
logger.error("Entered password ${password} of customer ${customer.id} is invalid");
Instead do:
logger.error("Entered password of customer ${customer.id} is invalid, cause of missing special character");