8
Logging and Monitoring Your Application
Maintaining records and metrics provides us with many advantages during our development cycle. They can help us increase our application’s performance, observe issues before they become problems, and give us insights into the application’s state. Logging and monitoring your application can reduce the time your development (and debugging) takes, as well as the number of headaches you acquire throughout the project. Logging is something that is often overlooked or treated with minimal afterthought, but it could make the difference between losing an hour’s worth of uptime or an entire day’s worth.
Suppose we had an application that simply inserted the details of a registration form into a database table. One day, the team accidentally renamed the first_name column to firstname and now no new records were being inserted. With logging, we would see something along the lines of a “first_name column does not exist” type of error. This would help guide us into looking at the database’s schema and figuring out where the disconnection is occurring (in this case, our typo from removing the underscore).
What if the error was more complex than that though? Our application is now running in a cluster and each node within the cluster receives a unique message exclusively from the other nodes. Occasionally, we would notice our table was missing some records without a clear pattern from the data itself. Using a logging mechanism, we would occasionally see a Could not establish connection error. We can double-check our connection pooling management (if applicable) or test each node if we can successfully connect to the database. On a small cluster, this would not be a problem, but on a large system, this could become tedious and time-consuming.
A solution for helping manage applications in a larger cluster would be to customize (or add) additional context to your application’s logging records. Meta-information such as the machine’s identifier could have helped us in the previous example. Sequelize offers a way to customize our logging, using an options.logging parameter, with the ability to change the logging behavior with different method invocations.
In this chapter, we will be covering the following topics:
- Configuring logging with all of the available interfaces
- Integrating third-party logging applications such as Pino or Bunyan
- Collecting metrics and statistics for Sequelize with OpenTelemetry
Technical requirements
You can find the code files for this chapter at https://github.com/PacktPublishing/Supercharging-Node.js-Applications-with-Sequelize/tree/main/ch8
Configuring logging with all of the available interfaces
Sequelize offers a few overload signatures for incorporating logs into an application. The default behavior is to call console.log for each query. The following is a list of signatures that Sequelize will abide by:
- function (msg) {}
- function (...msg) {}
- true/false
- msg => someLogger.debug(msg)
- someLogger.debug.bind(someLogger)
If we wanted to customize Sequelize’s logging behavior, the following example would be a quick introduction to how to do so:
function customLog(msg) {
// insert into db/logger app here
// ...
// and output to stdout
console.log(msg);
}
const sequelize = new Sequelize('sqlite::memory:', {
logging: customLog
});In addition to Sequelize sending the SQL queries into our customLog function, we are also given a helper method for when we need to log additional info beyond our queries. The Sequelize instance provides a log method and can be called as shown here:
sequelize.log('this will send our message to customLog as
well');If your Sequelize instance’s benchmark parameter is set to true, then Sequelize will add the total elapsed time for the query to complete at the end of the message. Using our previous example, a log entry might look something similar to this:
Executed (default): SELECT * FROM ...; Elapsed time: 136ms
Sometimes, we will want to log the log query, query objects, applicable parameters, or any other form of metadata. Sequelize will recognize the spread pattern for this type of support:
function multiLog(...msgs) {
msgs.forEach(function(msg) {
console.log(msg);
});
}
const sequelize = new Sequelize('sqlite::memory:', {
logging: multiLog
});We can now call the Sequelize instance’s log method, which will send the parameters to our multiLog function as follows:
sequelize.log('error', 'custom error message', Date.now(), { id: 100 });This would print each parameter onto its own newline due to the behavior of the multiLog function.
The logging parameter can also accept a Boolean value. The true value will coalesce into Sequelize’s default behavior (console.log). Setting the value to false would disable logging completely and nullify any log invocations. The following example would prevent Sequelize from logging queries:
const sequelize = new Sequelize('sqlite::memory:', {
logging: false
});Note
The true value for logging is considered deprecated and is not preferable to omitting the logging value for the default behavior or using console.log as the parameter’s value.
Sequelize can also limit logging to specific queries with the logging parameter on each queryable method (for example, findAll, update, and create). For instance, if we wanted to disable logging on a specific query, we can do so by setting the following query’s logging parameter to false:
sequelize.findAll({
where: {
id: 1
}
}, {
logging: false
});Note
You can also see a log output of queries by taking advantage of Sequelize’s use of the debug NPM package. By setting the environment variable to DEBUG=sequelize:sql*, your terminal should show queries executed by Sequelize.
Integrating third-party logging applications such as Pino or Bunyan
If our application already utilizes a third-party application for logging, Sequelize can offer support for integrating with such systems. This section references two logging applications, Pino and Bunyan, but any logging library or framework should also be compatible with Sequelize.
Integrating with Pino
Pino is a low overhead Node.js logger that also offers redaction, transport, and asynchronous support. Presuming our project has Pino installed within our node_modules folder, we can simply integrate it with our Sequelize instance as follows:
const logger = require('pino')();
const sequelize = new Sequelize('sqlite::memory:', {
logging: (msg) => logger.debug(msg)
});Now, when we call sequelize.log manually or execute queries, the logs will be sent to the Pino logging library. The output would look similar to this:
{"level":30,"time":1650118644700,"pid":5363,"hostname":"MacBook-Pro-4.local","msg":"Executing (default): SHOW INDEX FROM `Airplanes` FROM `airline`"}For more information on Pino, you can refer to the project’s repository at https://github.com/pinojs/pino.
Integrating with Bunyan
Sometimes a logging framework requires an intermediary step before being able to bind the framework to Sequelize. An example of this would be the Bunyan framework. Bunyan is a logging framework that focuses on offering serialization and streaming methods. Integrating this framework would look similar to the following:
const bunyan = require('bunyan');
const logger = bunyan.createLogger({name: 'app'});
const sequelize = new Sequelize('sqlite::memory:', {
logging: (msg) => logger.info(msg)
});The preceding example shows the output of Bunyan’s logging with Sequelize:
{"name":"app","hostname":"MacBook-Pro-4.local","pid":6014,"level":30,"msg":"Executing (default): SHOW INDEX FROM `Airplanes` FROM `airline`","time":"2022-04-16T14:33:13.083Z","v":0}For more information on Bunyan, you can refer to the project’s repository at https://github.com/trentm/node-bunyan.
From the Pino and Bunyan examples, we can see that adding a logging framework already resolves our unique machine identifier, the time of the error, and urgency research. By looking at the logs, it should now be easier to sift through wherever an error is occurring within clusters or applications.
We can now finish integrating a logging framework within the Avalon Airlines project. From the project’s root directory, we will need to install the necessary package:
npm i pino
Within models/index.js, see the following line:
const Sequelize = require('sequelize/core');Export the Pino framework underneath with a constant:
const logger = require('pino')();After exporting the constant, see this line:
const db = {};Underneath, we can add the logging parameter to the config object as follows:
config.logging = (msg) => logger.info(msg);
Now, our application supports custom logs using the Pino logging framework.
Collecting metrics and statistics for Sequelize with OpenTelemetry
OpenTelemetry is a standardized specification for collecting, aggregating, and instrumenting various statistics, metrics, traces, and logs. OpenTelemetry can help us identify where bottlenecks may occur, categorize and apply topological filters on logs, and plug into third-party applications (for example, for alert monitoring).
To integrate OpenTelemetry with Sequelize, we would need to install the following packages within our Avalon Airlines project:
npm i @opentelemetry/api @opentelemetry/sdk-trace-node @opentelemetry/instrumentation @opentelemetry/sdk-node @opentelemetry/auto-instrumentations-node opentelemetry-instrumentation-sequelize
Within models/index.js, under the 'use strict'; line, we can now add our new packages:
const { NodeTracerProvider } =
require(‹@opentelemetry/sdk-trace-node');
const { registerInstrumentations } =
require('@opentelemetry/instrumentation');
const { SequelizeInstrumentation } =
require(‹opentelemetry-instrumentation-sequelize');Just above the let sequelize; line, we can add the trace provider, which will register the correct Sequelize OpenTelemetry plugin:
const tracerProvider = new NodeTracerProvider({
plugins: {
sequelize: {
// disabling the default/old plugin is required
enabled: false,
path: ‹opentelemetry-plugin-sequelize'
}
}
});Below the traceProvider declaration block, we can associate the provider with the Sequelize instrument specifications:
registerInstrumentations({
tracerProvider,
instrumentations: [
new SequelizeInstrumentation({
// any custom instrument options here
})
]
});Note
You can find additional references and option parameters for Sequelize instrumentation at https://github.com/aspecto-io/opentelemetry-ext-js/tree/master/packages/instrumentation-sequelize.
At the root directory of the Avalon Airlines project, create a file called tracing.js with the following code:
const opentelemetry = require("@opentelemetry/sdk-node");
const { getNodeAutoInstrumentations } =
require(«@opentelemetry/auto-instrumentations-node");
const sdk = new opentelemetry.NodeSDK({
traceExporter: new opentelemetry.tracing.
ConsoleSpanExporter(),
instrumentations: [getNodeAutoInstrumentations()]
});
sdk.start();Now, we can call our application with the following command:
node -r "./tracing.js" index.js
After that, open a browser to the project’s URL (by default, http://localhost:3000/) and refresh the page a few times. After a few seconds, you should see some events within your terminal that look similar to this:
{
traceId: '7c25880d655f67e5d8e15b83129dc95e',
parentId: '934dc0ed012f6e37',
name: ‹SELECT›,
id: ‹af16347a3fbbf923›,
kind: 2,
timestamp: 1650124004289597,
duration: 1616,
attributes: {
‹db.system': 'mysql',
‹net.peer.name›: ‹127.0.0.1›,
‹net.peer.port': 3306,
‹db.connection_string':'jdbc:mysql://127.0.0.1:3306/
airline›,
‹db.name›: ‹airline›,
‹db.user': 'root',
‹db.statement': 'SELECT `id`, `planeModel`,
`totalSeats`, `createdAt`, `updatedAt` FROM
`Airplanes` AS `Airplane`;›
},
status: { code: 0 },
events: []
}Traditionally, the application would export this data to a collector such as Zipkin (https://zipkin.io/), Jaeger (https://www.jaegertracing.io/), or Prometheus (https://prometheus.io/). For instructions on how to associate the application’s telemetry data, you can refer to this tutorial here: https://opentelemetry.io/docs/instrumentation/js/exporters/.
If you were to use Zipkin as your collector, then under the const tracerProvider = new NodeTracerProvider({ block within models/index.js, we would replace this line:
provider.addSpanProcessor(new BatchSpanProcessor(new ZipkinExporter()))
We need to replace it with the following:
tracerProvider.addSpanProcessor(new BatchSpanProcessor(new ZipkinExporter()));
This will tell our trace provider to export the traces and logs to the Zipkin Exporter (multiple exporters can be used at the same time).
Summary
In this chapter, we went through the different overload signatures for configuring logging with Sequelize. We also learned how to integrate third-party frameworks, such as OpenTelemetry, within our Node.js application.
In the next chapter, we will be covering how to integrate plugins, or adapters, into our Sequelize instance. The following chapter will also demonstrate how to create our own adapter.