苏格团队

作者：MaxPan

交流QQ群：855833773

背景

在自定义Egg.js的请求级别日志这篇文章中，我们实现了自定义请求级别的日志模块。看上去功能是完整了，但好像还缺点什么。

大家在根据日志追查问题的过程中，很多时候看到了某条log信息想去找出处，但是实际上代码里面打相同类型的log地方可能不止一处，这时你就比较难去定位这行log到底是哪里打的。

举个最极端的例子

//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');
    }
}

上面的例子虽然比较极端，但是我们在代码中难免会碰到类似的情况。两个route对于的controller中都打印了相同的log，你在查日志的时候，是无法区分log到底是first里面打的还是second里面打的。

这个时候，我们就需要在日志打印的时候，同时也将调用日志时的文件名和代码行数记录下来一并打印，效果如下

[2018-11-02 19:25:09.665][22896][home.js:4][/] in controller

开始动手

查了很久的Nodejs文档，发现Nodejs的api中并没有直接提供我们想到的信息，所以只能另找出路。

回忆我们以往的开发，这类的信息好像只有在Nodejs抛出异常的时候看到过。每当Nodejs抛出异常时，我们都能看到一堆异常调用的堆栈，里面就有我们想要的信息，我们从这开始入手。

我们先手动创造一个异常对象，并打印出来

function getException() {
    try {
        throw Error('');
    } catch (err) {
        return err;
    }
}
        
let err = getException();
console.log(err);

console的信息如下图：

在图上我们可以看到，我们想要的信息

err对象在console的时候，会直接输出err对象中的stack属性，该属性是个字符串，我们可以通过一系列的字符串操作，拿到我们想要的文件名和行数。

接下来我们开始对日志模块代码进行改造，新增一个getCallerFileNameAndLine方法，如下：

getCallerFileNameAndLine(){
    function getException() {
            try {
                throw Error('');
            } catch (err) {
                return err;
            }
        }
        
    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 '[-]';
    }
}

最终结果

最后我们每条打印的日志后面，都会跟上文件名和行数

有的同学可能担心，每次打log都抛一个异常，会不会对性能造成影响。

我在getCallerFileNameAndLine方法前后进行打点统计，平均执行时间在2ms左右，所以是可以忽略不计的。