Think Ahead, Think Logging
When we develop an application, we have everything we need to understand the application's behavior. Debugger, traces, tests – all of this information is right in our hands. If something goes wrong, it’s not so hard to track the problem.
But the situation is completely different when the app leaves our development box and goes to production. In the best case, we’ll receive an email or tweet from a user, but typically problems remain in production silently, while customers just silently leave.
Preparing an application for production means preparing good error logging. I’m going to show you how to extend your Express.js with proper logs.
What it means to have good logs?
In my perspective, good logs are those satisfying the following criteria:
- All unhandled errors are logged
- Log records are comprehensive and clear
- Logs are easily accessible
- If critical error logged, developers have to be notified
Logger is object responsible to take some message or object and log it. The example of one,
Logger could be used everywhere you need to get some info. But our ultimate goal is to be aware of all errors might appear in application.
Augmenting Express.js application with logs
We never know then error might appear. But, we can catch all unhandled errors + if some web request failed to complete with success code, we have to log that as well.
Handling “unhandled” errors
We can listen to process ‘uncaughtException’ event. It just placed in
app.js file. The best place is just after require section and before any object is used.
From official docs,
Emitted when an exception bubbles all the way back to the event loop. If a listener is added for this exception, the default action (which is to print a stack trace and exit) will not occur.
So, we just redirecting that error to logger. Also, docs say following:
Don’t use it, use domains instead. If you do use it, restart your application after every unhandled exception!
I still not switched to domain version for that, need to consider that advice.
uncaughtException will give us only information typically about
undefined variables used, that’s pretty simple to caught during development testing. More interesting stuff is what’s actually happening on runtime, while application handling HTTP requests.
Logging failing HTTP requests
Express.js power feature is middleware. It’s possible to do a lot of cool stuff based on middleware functions. We’ll utilize that feature to create a few middleware function that would allow to log all failed HTTP requests.
Look a bit closer:
logError() produces middleware function that expected to be the last in chain, and if previous function retured an error, it stores that error object in in requests.
logHttpErrors() produces middleware function that would override response
.end() function and logs warning or error, depending on response status code.
Let’s integrate to app.
logHttpErrors() could be put into
It’s a bit more trickier with
logError() function. As I said above, it have to be last callback in chain.
So, it’s only possible to apply it in
app.configure() since the routes are not defined yet. Even it’s possible to manually add it to each endpoint manually, I don’t think it’s good idea, because it’s easy to forgot do that.
I came up to following solution,
Now, it’s everything in place, so all
4xx are logged as warnings, all
5xx are logged as errors.
Move your logs to cloud
Simply logging information is not enough. While your application writes info to console on production machine, this information worthless to you. You have to put you logs to the place where is easily accessible.
There are few services like that. One of I recently hooked with in Logentries.
Logentries gives you API to submit information there + Dashboard, there logs can be viewed, search and analyzed.
And now, we need to update logger, to not only
console.log but send it to Logentries.
Will create Logentries client,
Will extend existing logger and override current
Checkout this gist where you can see all things put together.
So, now wherever
logger is used, logs will both shown to screen (which is cool for development) and submitted to Logentries (which is cool for production).
Setup notification on critical errors
If error appeared on production, developers attention should be there. Without good notification system, is too easy to skip the moment then error arises.
Again, it’s easy to do with Logentries. Just go to
Alerts section and setup patterns of errors you interested and email addresses for notifications.
Email is not only one option, you can setup for SMS or webhook for your app. So, anytime error or warning appeared you will be notified and take action on it.
I’ve used that for likeastore app I currently working on and it works just fine. Having such logs gave a lot of information after we went to private-beta phase. When you see how application behaves then real users start to use, it gives you good insights about fixes and improvements to apply.
Taking into account that approach above is very universal and easy to adopt, to it today.