Winston Under The Hood For Beginners— [Part 1]

Learn how your data flows inside your logger.

Do you use Winston in your application and are curios how it operates on your data as it delivers it to its destination? Maybe you are facing a problem and need a quick overview of how Winston works under the hood or just would like to learn how the package was constructed for learning purposes —In any of those cases, you are at the right place!

I follow a routine where I spend one hour every morning reading random repositories and Winston was one of those packages that I enjoyed reading and so I decided to write about it hoping that it would be of value for beginners or anyone who would like to understand how Winston works under the hood.

In the future, I will be covering other popular packages.

Note that this is my first blog so please feel free to help me improve it by leaving tips in the comments section.

Table of Content

Expectations

What is Winston?

Winston’s file Structure

The winston Object

Creating a logger;
— — DerivedLogger class
— — Logger class

A Tour with ‘info’
— — Data flow overview
— — Setting up the logger
— — log( )
— — _transform( )

Wrapping up

Part-2

Expectations

This blog is for beginners. It will focus on the essential and basic parts that are responsible for transporting your data as well as how the package is constructed at a high level Which means we will NOT cover every part of this package. Just the basic data flow in a simple logging scenario.

My hope is that by the end of this post you will know how to navigate your way around in the Winston’s repository for any reason be it.

If you are just here for a quick overview of how Winston operates on your data under the hood then just skip to the Data Flow Overview section for a a quick overview diagram.

What is Winston?

The documentation describes winston as follows

winston is designed to be a simple and universal logging library with support for multiple transports

This is accurate, however, the question I’m trying to answer today is, what is Winston internally made up of?

At a high level, Winston is basically made up of 2 custom streams that transport your data from one place to another using an object called info and it performs some magic on it in between. very simple! right?

Maybe not. But don’t worry, I will break it down for you in more details but basically Winston takes your data and then it writes it to a Transform stream which in turn transforms the data and then pipes it to a Transport stream which finally delivers it to its destination — whether its a file, the Console or any other destination.

So In order to understand how Winston works under the hood, you need to first understand how streams work (especially the transform stream). I would suggest reading the blog post below written by the very talented Samer Buna.

Node.js Streams: Everything you need to know

Winstons Structure

I wasn’t sure if I should include this section but then I thought it is good to keep a picture in our mind of how the files are structured before we start. The lib directory here is where you will find most of the code we are concerned with in part-1 of this blog. I numbered the files in the manner they are called when creating your logger.

With this in mind, let's look at what makes up the winston object we import in our application. To do that, we need to look at lib/winston.js module where the winston object is created and exported from.

The winston Object

Note that in all the snapshots used in this blog, comment code may be removed and irrelevant implementation details might be minimized to only show the functions names and make code more readable from a high level view.

When you require winston in your module, what actually gets called is ‘lib/winston.js’ module.

lib/winston.js exports the object winston in section (0) and then in section (1) it adds public properties to it among of which are createLogger, Transport and format which you should be familiar with. Note that some of these properties will be imported dynamically (i.e. on demand using inline require() ) from their corresponding modules when you use them.

In section (2) the default logger is created and its default methods are attached to winston in case you use the default logger, you know where to find it. Section (3) is where friendly warnings are added to some properties.

Creating a Logger

To create a custom new logger we call winston.createLogger(options) and give it our options object which includes the Transport stream, the level property, and some formatting. But What is createLogger?

DerivedLogger class

When you call ‘createLogger’ with your custom options object, you are actually calling a factory function inside the ‘create-logger.js’ module. This factory function instantiates the DerivedLogger class and returns a new instance — which is your logger. Let’s have a look at this factory below. For more on why a factory function is used read notes [1] of this section.

This instantiated DerivedLogger class extends the Logger class which lives inside the ‘logger.js’ module where most of the logger’s functionality is implemented. Lets look at DerivedLogger class from a high level view:

You might wonder then, what is the purpose of DerivedLogger? Its purpose, as the comments imply, is to add optimized methods to the instance’s prototype which in turn allows the user to do logger.info(‘message’) rather than logger.log(‘info’, ‘message’), recognize the pattern? To see how it adds those methods read the code inside the _setupLevels() function here.

Now that we know what the DerivedLogger class does, let's take a look at the extended logger class and see how this class builds your logger instance.

Logger class

This class is the core class responsible for creating your logger. It first extends the Transform stream and then configures the state of the logger inside the constructor based on the options the client provided.

This class then adds some methods to the prototype. Some of those methods are for public use such as the log() method and some are for internal use only such as the _transform() method. This is how the class looks:

First, note that this class extends the Transform stream and calls super() with the objectMode option set to true. Doing so makes dealing with transported data less of a hassle as opposed to transporting binaries.

Extending the Transform stream allows class to implement our custom Transform stream through implementing the _transform() function on line 187. This in turn allows us to write to this stream from anywhere in our class by calling this.write(data) and we can also pipe from it by calling this.pipe(nextStream) .

So in other words, _transform is an implementation for the extended Transform stream which must be implemented in our class in order to tell the Transform stream what to do with the data that we are writing to it before it sends it to the next piped stream. After all, it is named Transform so we must tell it how to transform our data.

The way I like to think about the _tranform method is similar to a life-cycle hook in React. It is called by the transform stream internally and data is then passed through it every time we call this.write(info). We will discuss the _tranform function in more details soon in our log tour.

let's now take a look at how Logger sets our state through the configure() function:

Loggers configure function which sets the state

As you can see, multiple state variables are set here using the options provided by the client (which are destructured in the parameters on line 46 using ES6 syntax).

One important line of code to note here is online 66. This is where the Transport stream (provided by the client) is piped to our extended Transform stream. Without this piping, our data doesn’t know where to go after leaving the extended Transform stream. This piping is done using the add() method.

Below is how the add method looks like; Piping happens on line 247.

logger’s add method

Notes:

• [1] Factory functions can be used instead of exporting the class itself for multiple reasons. The most important in my opinion is it allows for flexibility where the client is not tied to a certain implementation of the Logger class which means developers can make changes later without breaking your code. To read more on why to use factory function, I recommend checking this detailed answer.
• [2] Transport and Tranfrom streams can be confusing because they hold similar names. TranFORM stream is the stream we create and implement which takes the users data and modifies/transforms it and then pipes it to the TransPORT stream — such as Console or File — which the user originally provided in the options. This TransPORT stream then writes this data to its final destination. So the TransPORT stream is provided by the user while the TransFORM is our own stream used to modify data. We will discuss the TransPORT stream implementation in part-2 of this blog but here today we will be covering the Transform stream. got a headache yet?!

A Tour With ‘info’

Now that we know how our logger instance is created and piped to the Transport stream, let's go on a tour with some fake data that we will be logging.

Before we start our tour, I want to remind you that Winston internally creates an object called info that is then used to transport and work on your data starting from the log method all the way to its final destination. In this tour, we will travel with this info object and explain what happens to it at each stop as we go through them so get ready and buckle up!

Data Flow Overview

Before we set up our logger and go on our tour in details, I want to share with you an overview flow-chart of the trip. I created this diagram in an attempt to visualize how our data flows under the hood from the moment you log it all the way to its final destination.

Don’t worry if it looks complicated or if it doesn’t make sense yet because we will go through each step in details but for those who are comfortable with streams and just want an overview I hope this helps.

Note that the Transport stream level and below will be covered in part-2 of this post.

logging data flow

Setting up the Logger

In order to go through our trip, lets first create our simple logger with a File Transport that writes to ‘logs.log’ and let's also add some basic formatting:

Then we will log some information and set the level value to ‘warn’:

Now let's see what happens to our data next after calling the log method.

[1st Stop] — log ( ‘ warn ’, ‘ Tour data ’ );

Log() is our first stop which is located inside the 'Logger.js' module. It receives the clients input as arguments and then its only job is to turn those inputs into a custom object called info and then writes info to our Transform stream.

Note that the info object in this function might be called differently depending on the client input but just think of it as the object that will be used to hold our data and is then sent to the stream.

There are three ways in which the client can log data in Winston using the log method. The log function optimizes for each one of those three cases. In each case, it creates an info object and writes it to the Tranform stream. let's have a look at a visual representation of those three cases and see how our info object created by the log method would look like before it is written to the stream:

Note that regardless of the clients input we see a [LEVEL] property added to the info object which holds a copy of the level property. This [LEVEL] property might scare you but it is simply a Symbol property which was added as an immutable copy of level. In other words, if the user provided { “level”: “info” } then after adding the [LEVEL] property, the object would look like this: { “level”: “info”, [LEVEL]: “info” }. very simple.

The Symbol property was added because the regular level (non-symbol) property might be changed when formatting later in the code but we need to keep an unchanged copy of it in our info object for reference.

Also, as a bonus, Symbols are not convertible to JSON so we don’t need to worry about removing it later when we convert to JSON at our final destination. For that reason using a Symbol here was a great option.

This [LEVEL] Symbol is imported from a library called ‘triple-beam’ which is a very simple library that exports a symbol for the ‘level’ property that can be used across multiple modules.

Now that we know what ‘log’ does and why symbols are added let's take a look at the actual code responsible for this logic inside of thelog method below and go through the first optimized case in details because even though the code can be self-explanatory, the naming can be confusing to some.

[CASE 1] The first optimized case -line 139- is when the client calls log and only provides one argument just like in our diagram’s first scenario. In this case, it is assumed that the client provided a JSON object as the first parameter, namely ‘level’, which contains all the options, such as ‘level’ and ‘message’, as properties.

This user-provided JSON object, namely param ‘level’ here, is then treated as the info object and so creating a new object named info is NOT needed and you can think of the level param in this if-statement as being our info object (notice the interesting comment on line 140).

so to recap, In all three scenarios, we see that a custom info object is created (in some cases an existing object provided by the client is treated as the info object) and then written to the Transform stream. An important property that we see added in all three cases is the Symbol [LEVEL] property which soon you will see why it was needed. Let’s now go to our next and 2nd stop with our info object.

Notes:

• You might wonder where the this.write property comes from. It simply comes from the extended Transform stream. Anytime you call write on your logger class it then writes to the transform stream which we implemented using _tranform function.

[2nd Stop] — _tansform(info)

After the info object in log() is written to the transform stream by calling this.write(info) it is then passed through the _transform(info) function. This function, as you might remember, was implemented by Winston when it created our Logger instance inside the 'logger.js' module.

Transform stream is like a middleware between the log() method and the Transport stream. It’s job is to apply formatting to our info object and ensure that it has the proper data.

let's take a look at the code inside _transform and see what happens to our info object here:

As we can see, the main operation that takes place at this stop can be found in section 3 which is basically formatting our info object (such as colorizing and adding a timestamp) and then writing it to the next piped stream — which in our case is the File Transport stream — by calling this.push( info )on line 222 (for more on push read Notes [1]).

Any formatting or push error is caught and thrown and the callback function is called in the finally{ }block to avoid blocking the transform stream in case of any errors occurring— allowing new data to keep flowing anyways ( for more on this callback read note [2] ).

Going back to our tour example lets take a look at a visual diagram of how our info object looks like after exiting _transform and before it is piped to the Transport Stream. Changes to our info object are highlighted in green:

As we can see, the level property was mutated after colorizing level. So had we not left an immutable property [LEVEL] we could have lost reference to the ‘warn’ value. Also, a timestamp property was added here. This modified info Object is finally sent to the FileTransport stream by calling this.push(info). Part-2 of this post will discuss what happens at the next stop.

Notes:

• [1] you might wonder why we use the push method and where it comes from? it simply is a method provided to us by the extended Transform stream which allows us to push our data to the next stream in line after we are done modifying it.
• [2] the callback function is passed to the _transform() function as a third argument which must be called to allow for new data to be passed in. If it is not called then the stream assumes we are not done with modifying our data and is therefore blocked.

Wrapping up

Until now, we saw how our logged data traveled through our logger all the way to the piped Transport stream passing through log() and _transform() methods. log creates the info object and adds a Symbol [LEVEL] property and then writes it to the Transform stream which in turn passes it through the _tranform() function; this function adds formatting to our info object and does some error handling before pushing it to the piped Transport File stream which we will cover in part-2 of this blog.

Part-2

part-2 of this blog will follow our info object as it goes through the implementation of the Transport stream all the way to its final destination ‘logs.log’.

If you enjoyed part-1, feel free to follow my blog to get notified when part-2 is published and don’t forget to add any remarks you might have in the comments below!