Node.js Winston logging with source lines example

README.md

why?: By default, winston doesn't show where the log comes from (function, file, line number...). This gist tries to workaround that limitation. code source: winstonjs/winston#890

BENCHMARK.txt

## method
disable line no / file name logging: comment out line 10~13 in `index.js`
benchmark use `gocannon`: ./gocannon http://localhost:3000 -d 10s -c 50

## summary
without: 3495 req/s
with: 3204 req/s
perf cost: ~8.3%

## without line no / file name logging
Attacking http://localhost:3000 with 50 connections over 10s using 4 CPUs
gocannon goes brr...
Total Req:     34952
Req/s:          3495.20
Interval stats: (interval = 250ms) 
|--REQS--|    |------------------------LATENCY-------------------------|
     Count           AVG         P50         P75         P90         P99
       458     25.8442ms   23.3829ms   27.2571ms   32.2578ms   49.5821ms
       569     22.1120ms   21.8482ms   23.0722ms   24.1072ms   25.7898ms
       594     21.0490ms   20.6712ms   21.5269ms   22.6293ms   26.3451ms
       690     18.1833ms   17.9538ms   19.1818ms   20.4899ms   30.9507ms
       719     17.4896ms   16.4754ms   18.2747ms   22.1431ms   32.7838ms
       768     16.2350ms   16.1180ms   16.8924ms   17.7465ms   19.5314ms
       815     15.3881ms   15.0551ms   15.7312ms   17.1888ms   25.9920ms
       864     14.4900ms   14.1435ms   14.5879ms   16.6522ms   19.7990ms
       878     14.2161ms   14.1307ms   14.5715ms   15.6243ms   17.2240ms
       882     14.1489ms   14.0052ms   14.3521ms   14.8451ms   17.0768ms
       848     14.7781ms   13.6755ms   14.8186ms   19.2275ms   26.9868ms
       879     14.2383ms   13.7428ms   14.5117ms   16.1441ms   24.7835ms
       885     14.0974ms   13.3969ms   14.0188ms   17.8626ms   20.5165ms
       947     13.1151ms   13.1192ms   13.4033ms   13.5918ms   15.3343ms
       905     13.8797ms   13.6873ms   14.4155ms   15.3361ms   17.5092ms
       894     13.9085ms   13.3956ms   13.8387ms   16.3138ms   20.7168ms
       949     13.2528ms   13.0991ms   13.5689ms   14.5484ms   15.5259ms
       931     13.4792ms   13.1328ms   13.7163ms   16.1166ms   19.9574ms
       930     13.3030ms   13.3488ms   13.8446ms   15.1255ms   19.1597ms
       960     13.0987ms   12.9476ms   13.4628ms   14.3893ms   17.5773ms
       829     15.0613ms   14.0233ms   14.8693ms   17.6066ms   28.4333ms
       938     13.3049ms   13.3658ms   13.7919ms   14.2921ms   15.5163ms
       896     13.9752ms   13.4951ms   14.1176ms   17.2068ms   21.7407ms
       988     12.6860ms   12.5219ms   13.1900ms   14.7095ms   16.0405ms
       937     13.2674ms   12.9765ms   13.5940ms   15.7229ms   19.1452ms
       965     12.9722ms   12.7691ms   13.1163ms   14.5703ms   17.4133ms
       963     12.9934ms   12.8559ms   13.3873ms   14.3052ms   15.0799ms
       957     13.0464ms   12.8626ms   13.2365ms   14.0347ms   17.0460ms
       953     13.1252ms   12.8791ms   13.6698ms   14.5584ms   15.6707ms
       758     16.3127ms   13.6787ms   17.7732ms   27.9488ms   39.4134ms
       970     13.0190ms   12.8637ms   13.4615ms   14.1488ms   15.7439ms
       937     13.2700ms   12.8959ms   13.3711ms   15.7014ms   25.9828ms
       899     13.8892ms   13.2595ms   14.3760ms   17.3312ms   20.3996ms
       918     13.7387ms   13.2634ms   14.5906ms   16.3839ms   22.9320ms
       974     12.8078ms   12.4575ms   12.9062ms   15.1095ms   19.1516ms
       968     12.8880ms   12.7404ms   13.1320ms   14.5098ms   19.6310ms
       942     13.2577ms   13.1053ms   13.5921ms   14.6262ms   18.2704ms
       948     13.1915ms   12.9714ms   13.7257ms   15.6529ms   21.7514ms
       916     13.5281ms   13.3490ms   13.8036ms   14.2574ms   19.0630ms
       931     13.5173ms   13.3797ms   13.6633ms   14.6346ms   16.5966ms
----------
     34952     14.2901ms   13.3958ms   14.6026ms   17.7465ms   26.7069ms
Responses by HTTP status code:
  200  ->   34952


## with line no / file name logging
Attacking http://localhost:3000 with 50 connections over 10s using 4 CPUs
gocannon goes brr...
Total Req:     32043
Req/s:          3204.30
Interval stats: (interval = 250ms) 
|--REQS--|    |------------------------LATENCY-------------------------|
     Count           AVG         P50         P75         P90         P99
       432     27.5755ms   24.7449ms   27.1762ms   38.9615ms   61.4458ms
       555     22.4508ms   22.4334ms   23.4422ms   23.8177ms   25.1948ms
       572     21.8803ms   21.2945ms   23.4420ms   25.0340ms   29.5757ms
       685     18.2078ms   17.8909ms   19.3792ms   20.4553ms   29.5776ms
       701     17.9507ms   17.5373ms   19.0518ms   20.9483ms   25.8483ms
       706     17.7859ms   17.0134ms   19.0553ms   22.1766ms   25.7361ms
       770     16.2938ms   15.6004ms   17.1695ms   19.4394ms   21.4295ms
       833     15.0295ms   14.8916ms   15.3590ms   16.3660ms   16.8254ms
       865     14.4561ms   14.3586ms   14.9402ms   17.2988ms   21.7790ms
       861     14.4012ms   14.3298ms   14.9216ms   15.2871ms   15.6972ms
       831     15.1284ms   14.5429ms   16.0055ms   19.4530ms   25.9611ms
       812     15.2346ms   14.9929ms   15.7487ms   16.1371ms   18.8379ms
       868     14.5543ms   14.2480ms   14.8253ms   16.9966ms   17.3114ms
       864     14.4083ms   14.1180ms   14.5544ms   16.1599ms   19.8636ms
       855     14.6617ms   14.2212ms   14.8484ms   16.3958ms   20.8048ms
       886     14.0492ms   13.9436ms   14.3381ms   14.7308ms   16.7339ms
       901     13.9776ms   13.7766ms   14.3156ms   15.9564ms   17.4717ms
       838     14.7584ms   14.3752ms   15.0662ms   16.5879ms   23.1690ms
       825     15.1679ms   14.8319ms   15.3487ms   17.7969ms   21.9793ms
       814     15.2518ms   14.9577ms   15.8061ms   16.4585ms   19.1865ms
       860     14.7130ms   14.5644ms   15.0391ms   16.4494ms   22.6582ms
       831     15.0345ms   14.6650ms   15.2414ms   17.1102ms   19.0298ms
       855     14.6276ms   14.4125ms   15.1532ms   15.6730ms   18.3026ms
       867     14.4253ms   14.4473ms   14.8038ms   15.4259ms   16.5588ms
       867     14.4036ms   14.3030ms   14.7887ms   15.8689ms   16.8083ms
       872     14.3425ms   14.2776ms   14.6434ms   15.0936ms   17.1534ms
       839     14.8852ms   14.3241ms   14.7169ms   19.3854ms   20.2019ms
       841     14.7220ms   14.5203ms   14.9814ms   15.6032ms   18.2284ms
       811     15.5508ms   15.2127ms   15.9921ms   18.1572ms   20.6724ms
       888     14.0586ms   13.8034ms   14.4153ms   15.1900ms   17.6392ms
       970     12.9712ms   13.4499ms   14.3082ms   14.8291ms   15.8381ms
       313     39.4220ms   14.4465ms   17.9910ms  167.9722ms  170.8162ms
       841     14.9566ms   14.5815ms   15.4027ms   16.6175ms   18.2388ms
       833     15.0414ms   14.7481ms   15.2262ms   16.8827ms   20.4082ms
       824     15.1230ms   14.8337ms   15.5041ms   16.3993ms   22.4337ms
       838     14.9308ms   14.3337ms   15.0785ms   18.7772ms   21.0754ms
       789     15.8302ms   15.5121ms   16.6774ms   18.0671ms   21.2681ms
       871     14.3293ms   14.1187ms   14.6803ms   15.2785ms   17.1435ms
       881     14.1797ms   14.0712ms   14.7812ms   15.3772ms   20.0545ms
       878     14.2621ms   14.2022ms   14.7461ms   15.4875ms   16.3227ms
----------
     32043     15.5877ms   14.5811ms   15.6429ms   18.6193ms   26.2815ms
Responses by HTTP status code:
  200  ->   32043

index.js

const express = require('express')
const logger = require("./logger");
const app = express()
const port = 3000

function someFunc(){
  logger.info("great job!")
}

app.get('/', (req, res) => {
  res.send('Hello World!')
  someFunc()
})

app.listen(port, () => {
  console.log(`Example app listening on port ${port}`)
})

logger.js

const winston = require("winston");
const StackElements = require("./stackElements");

const logger = winston.createLogger({
  level: "debug",
  format: winston.format.json(),
  transports: [new winston.transports.Console()],
});

logger.old_info = logger.info;
logger.info = function(msg, ...vars) {
    logger.old_info(StackElements.getFormatedStackTraceElement(1) + ": " + msg, ...vars);
}

module.exports = logger;

stackElements.js

const path = require('path');

class V8StackElements {
    static get stack() {
        return this.customStack;
    }

    constructor(callerIndex) {

        // Use V8's feature to get a structured stack trace
        const oldStackTrace = Error.prepareStackTrace;
        const oldLimit = Error.stackTraceLimit;
        try {
            Error.stackTraceLimit = callerIndex + 1; // <- we only want the top couple of elements
            Error.prepareStackTrace = (err, structuredStackTrace) => structuredStackTrace;
            Error.captureStackTrace(this);
            this.customStack = this.stack; // <- invoke the getter for 'stack'
        } finally {
            Error.stackTraceLimit = oldLimit;
            Error.prepareStackTrace = oldStackTrace;
        }
    }
}

class StackElements {
    static getFormatedStackTraceElement(callerIndex = 0) {
        callerIndex = callerIndex + 2; //ignor v8 level and this level
        const stack = new V8StackElements(callerIndex).stack;
        const element = stack[callerIndex];
        const fileName = path.basename(element.getFileName());
        return element.getFunctionName() + "(" + fileName + ":" + element.getLineNumber() + ")";
    }
}

module.exports = StackElements;

on error stack: https://stackoverflow.com/questions/47231677/how-to-log-full-stack-trace-with-winston-3

// my-loader.js
module.exports = function(source) {
  // get the file name from webpack
  const fileName = this.resourcePath.split('/').pop();
  // replace console.log with console.log('[file-name:line-number]', ...)
  return source.replace(/console\.log\((.*)\)/g, (match, args) => {
    // get the line number from match index
    const lineNumber = source.substr(0, match.index).split('\n').length;
    // return new console.log statement
    return `console.log('[${fileName}:${lineNumber}]', ${args})`;
  });
};

module: {
  rules: [
    {
      test: /\.js$/,
      use: ['./my-loader.js']
    }
  ]
}

Okay, I will explain my-loader.js line by line.

The first line exports a function that takes the source code as an argument and returns a transformed version of it. This is how webpack loaders work.
The second line gets the file name from webpack using this.resourcePath, which is a property that contains the absolute path of the current file. Then it splits the path by / and pops the last element, which is the file name.
The third line uses a regular expression to replace all occurrences of console.log(...) with console.log('[file-name:line-number]', ...). It uses a callback function to generate the new console.log statement based on the match and arguments.
The fourth line gets the line number from match index using source.substr(0, match.index).split('\n').length. It takes a substring of the source code from 0 to match index, which is where console.log starts. Then it splits it by \n, which is a newline character. Then it counts how many elements are in the array, which is equal to how many lines are before console.log. This gives us the line number.
The fifth line returns a new console.log statement with [file-name:line-number] added as a prefix to args. Args are whatever was inside console.log parentheses.