• Scotland team
  • Author: MaxPan
  • Communication QQ group: 855833773

background

In the article customizing request level logging for egg.js, we implemented a custom request level logging module. It looks complete, but there seems to be something missing.

In the process of tracing problems according to the log, many times you see a certain log information and want to find the source, but in fact, there may be more than one place in the code of the same type of log, then you can not locate the line of log exactly where.

Take the most extreme example

//home.js
class AppController extends app.Controller {
    async first() {
        this.ctx.swLog.info('in controller');
        await this.ctx.render('first.html');
    }
    
    async second(){
        this.ctx.swLog.info('in controller')
        await this.ctx.render('second.html'); }}Copy the code

The above example is extreme, but we can’t avoid similar situations in code. The same log is printed in the controller of both route pairs. When you check the log, you cannot distinguish whether the log is made in first or second.

In this case, we need to print the file name and the number of lines of code when the log is called. The result is as follows

[the 2018-11-02 19:25:09. 665] [22896] [home. Js: 4] [/]in controller
Copy the code

start

After looking through the Nodejs documentation for a long time, it turned out that the Nodejs API didn’t directly provide the information we wanted, so we had to find another way.

Recalling our past development, this kind of information seems to only be seen when Nodejs throws an exception. Every time Nodejs throws an exception, we see a stack of exception calls with the information we want, so we’ll start there.

We start by manually creating an exception object and printing it out

function getException() {
    try {
        throw Error(' ');
    } catch (err) {
        returnerr; }}let err = getException();
console.log(err);
Copy the code

The following figure shows the console information:

We can see the information we want in the picture

When the err object is console, it directly outputs the stack property in the Err object, which is a string. We can perform a series of string operations to get the file name and line number we want.

Next we will start to modify the logging module code by adding a getCallerFileNameAndLine method as follows:

getCallerFileNameAndLine(){
    function getException() {
            try {
                throw Error(' ');
            } catch (err) {
                returnerr; }}const err = getException();

    const stack = err.stack;
    const stackArr = stack.split('\n');
    let callerLogIndex = 0;
    for (let i = 0; i < stackArr.length; i++) {
        if (stackArr[i].indexOf('Map.Logger') > 0 && i + 1 < stackArr.length) {
            callerLogIndex = i + 1;
            break; }}if(callerLogIndex ! = =0) {
        const callerStackLine = stackArr[callerLogIndex];
        return ` [${callerStackLine.substring(callerStackLine.lastIndexOf(path.sep) + 1, callerStackLine.lastIndexOf(':'))}] `;
    } else {
        return '[-]'; }}Copy the code

The final result

We end up with the file name and line number after each printed log

Some students may be concerned about whether the performance will be affected by throwing an exception every time you log.

I made statistics before and after the getCallerFileNameAndLine method, and the average execution time is about 2ms, so it can be ignored.