日志打点一直是个调试最头疼的问题。如果直接在代码中插入埋点代码,不仅侵入性强而且工作量大也不够灵活,要是能做到智能打点就好了,koa-await-breakpoint 正是我们需要的。

6.1.1 什么是 koa-await-breakpoint

koa-await-breakpoint 是一个 Koa 的中间件,是一个在 routes/controllers 里(作用域包含 ctx)的 await 表达式前后自动打点的工具,不用插入一行日志打点代码,只需要在引入时配置一下,就可以记录每个请求到来时 await 表达式前后的现场,例如:

  1. await 表达式所在的文件及行列号(filename)。
  2. await 表达式是执行的第几步(step)。
  3. await 表达式字符串形式(fn)。
  4. 执行 await 表达式所花费的毫秒(take)。
  5. 执行 await 表达式的结果(result)。
  6. 当前请求的 ctx。

使用方法如下:

// On top of the main file
const koaAwaitBreakpoint = require('koa-await-breakpoint')({
  name: 'api',
  files: ['./routes/*.js']
})

const Koa = require('koa')
const app = new Koa()

// Generally, above other middlewares
app.use(koaAwaitBreakpoint)
...

app.listen(3000)

6.1.2 实现原理

  1. 重载 Module.prototype._compile,相当于 hack 了 require,如果发现是 require 了配置里指定的文件,则进行下一步,否则返回原始代码的内容,相关源代码如下:

    shimmer.wrap(Module.prototype, '_compile', function (__compile) {
     return function koaBreakpointCompile(content, filename) {
       if (!_.includes(filenames, filename)) {
         return __compile.call(this, content, filename);
       }
       ...
     };
    });
    
  2. 用 esprima 解析代码,生成 AST。例如:

    const Mongolass = require('mongolass')
    const mongolass = new Mongolass('mongodb://localhost:27017/test')
    const User = mongolass.model('users')
    
    exports.getUsers = async function getUsers(ctx) {
     await User.create({
       name: 'xx',
       age: 18
     })
     const users = await User.find()
     return users
    }
    

    会生成如下 AST,只截取了 await User.create(...) 相关的 AST:

    Script {
     ...
     AwaitExpression {
       type: 'AwaitExpression',
       argument:
        CallExpression {
          type: 'CallExpression',
          callee:
           StaticMemberExpression {
             type: 'MemberExpression',
             computed: false,
             object:
              Identifier {
                type: 'Identifier',
                name: 'User',
                loc: { start: { line: 6, column: 10 }, end: { line: 6, column: 14 } } },
             property:
              Identifier {
                type: 'Identifier',
                name: 'create',
                loc: { start: { line: 6, column: 15 }, end: { line: 6, column: 21 } } },
             loc: { start: { line: 6, column: 10 }, end: { line: 6, column: 21 } } },
          arguments:
           [ ObjectExpression {
               type: 'ObjectExpression',
               properties:
                [ Property {
                    type: 'Property',
                    key:
                     Identifier {
                       type: 'Identifier',
                       name: 'name',
                       loc: { start: { line: 7, column: 6 }, end: { line: 7, column: 10 } } },
                    computed: false,
                    value:
                     Literal {
                       type: 'Literal',
                       value: 'xx',
                       raw: '\'xx\'',
                       loc: { start: { line: 7, column: 12 }, end: { line: 7, column: 16 } } },
                    kind: 'init',
                    method: false,
                    shorthand: false,
                    loc: { start: { line: 7, column: 6 }, end: { line: 7, column: 16 } } },
                  Property {
                    type: 'Property',
                    key:
                     Identifier {
                       type: 'Identifier',
                       name: 'age',
                       loc: { start: { line: 8, column: 6 }, end: { line: 8, column: 9 } } },
                    computed: false,
                    value:
                     Literal {
                       type: 'Literal',
                       value: 18,
                       raw: '18',
                       loc: { start: { line: 8, column: 11 }, end: { line: 8, column: 13 } } },
                    kind: 'init',
                    method: false,
                    shorthand: false,
                    loc: { start: { line: 8, column: 6 }, end: { line: 8, column: 13 } } } ],
               loc: { start: { line: 6, column: 22 }, end: { line: 9, column: 5 } } } ],
          loc: { start: { line: 6, column: 10 }, end: { line: 9, column: 6 } } },
       loc: { start: { line: 6, column: 4 }, end: { line: 9, column: 6 } } },
     ...
    
  3. 遍历找到 awaitExpression 节点,进行以下包装后生成 AST,替换掉原来的节点。

    global.logger(
     (typeof ctx !== 'undefined' ? ctx : this),
     function(){
       return awaitExpression
     },
     awaitExpressionString,
     filename
    )
    

    相关源代码如下:

    findAwaitAndWrapLogger(parsedCodes)
    try {
     content = escodegen.generate(parsedCodes, {
       format: { indent: { style: '  ' } },
       sourceMap: filename,
       sourceMapWithCode: true
     })
    } catch (e) {
     console.error('cannot generate code for file: %s', filename)
     console.error(e.stack)
     process.exit(1)
    }
    debug('file %s regenerate codes:\n%s', filename, content.code)
    

    findAwaitAndWrapLogger 的作用就是遍历 AST,将 awaitExpression 替换成用日志函数包裹后新的 awaitExpression 的 AST。最后用 escodegen 将 AST 生成代码(支持 soucemap,所以错误栈对应的行数是正确的)。

核心:每个请求到来时,生成一个 requestId(可自定义,默认为 uuid)挂载到 ctx 上,这样就可以通过 requestId 将日志串起来了。

特点:可以记录每个请求的每一步(await 表达式)的现场及返回值,方便查日志。

6.1.3 使用 koa-await-breakpoint

测试代码如下:

app.js

const koaAwaitBreakpoint = require('koa-await-breakpoint')({
  name: 'api',
  files: ['./routes/*.js']
})

const Paloma = require('paloma')
const app = new Paloma()
const userRouter = require('./routes/user')

app.use(koaAwaitBreakpoint)
app.route({ method: 'GET', path: '/users', controller: userRouter.getUsers })

app.listen(3000)

routes/user.js

const Mongolass = require('mongolass')
const mongolass = new Mongolass('mongodb://localhost:27017/test')
const User = mongolass.model('users')

exports.getUsers = async function getUsers (ctx) {
  await User.create({
    name: 'xx',
    age: 18
  })

  const users = await User.find()
  ctx.body = users
}

运行:

$ DEBUG=koa-await-breakpoint node app.js

终端打印出转换后的代码,可以看出 routes/users.js 被转换成了:

const Mongolass = require('mongolass');
const mongolass = new Mongolass('mongodb://localhost:27017/test');
const User = mongolass.model('users');
exports.getUsers = async function getUsers(ctx) {
  await global.logger(typeof ctx !== 'undefined' ? ctx : this, function () {
    return User.create({
      name: 'xx',
      age: 18
    });
  }, 'User.create({\n    name: \'xx\',\n    age: 18\n})', '/Users/nswbmw/Desktop/test/routes/user.js:6:2');
  const users = await global.logger(typeof ctx !== 'undefined' ? ctx : this, function () {
    return User.find();
  }, 'User.find()', '/Users/nswbmw/Desktop/test/routes/user.js:11:16');
  ctx.body = users;
};

访问 localhost:3000/users,终端打印出:

{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","timestamp":"2018-02-26T06:31:31.100Z","this":...,"type":"start","step":1,"take":0}
{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","step":2,"filename":"/Users/nswbmw/Desktop/test/routes/user.js:6:2","timestamp":"2018-02-26T06:31:31.104Z","this":...,"type":"beforeAwait","fn":"User.create({\n    name: 'xx',\n    age: 18\n})","take":4}
{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","step":3,"filename":"/Users/nswbmw/Desktop/test/routes/user.js:6:2","timestamp":"2018-02-26T06:31:31.175Z","this":...,"type":"afterAwait","fn":"User.create({\n    name: 'xx',\n    age: 18\n})","result":{"result":{"ok":1,"n":1},"ops":[{"name":"xx","age":18,"_id":"5a93a9c3cf8c8797c9b47482"}],"insertedCount":1,"insertedIds":["5a93a9c3cf8c8797c9b47482"]},"take":71}
{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","step":4,"filename":"/Users/nswbmw/Desktop/test/routes/user.js:11:16","timestamp":"2018-02-26T06:31:31.175Z","this":...,"type":"beforeAwait","fn":"User.find()","take":0}
{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","step":5,"filename":"/Users/nswbmw/Desktop/test/routes/user.js:11:16","timestamp":"2018-02-26T06:31:31.180Z","this":...,"type":"afterAwait","fn":"User.find()","result":[{"_id":"5a93a9c3cf8c8797c9b47482","name":"xx","age":18}],"take":5}
{"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","timestamp":"2018-02-26T06:31:31.181Z","this":...,"type":"end","step":6,"take":1}

注意:type 是以下其中一种,take 的单位是 ms。

  1. start:请求到来时第 1 次打点。
  2. beforeAwait:上一个 awaitExpression 之后到这一个 awaitExpression 之前。
  3. afterAwait:这个 awaitExpression 开始到结束。
  4. error:错误日志,包含了错误信息。
  5. end:请求结束时打点。

6.1.4 自定义日志存储

store 参数最好自己定义(默认打印日志到 stdout),该参数是一个对象并且有一个 save 方法即可。在 save 方法内可做一些逻辑修改或者日志策略,比如:

  1. 添加日志标识(例如:name)方便区分不同服务的日志。
  2. 针对错误日志,添加一些额外字段方便追踪现场。
  3. 将日志发送到 Logstash 或其他日志服务。
  4. 限制日志频率,比如:只有响应时间大于 500ms 的请求日志才会被记录。

koa_await_breakpoint_store.js

exports.save = function save(record, ctx) {
  record.name = 'app name'
  record.env = process.env.NODE_ENV

  if (record.error) {
    record.error = {
      message: record.error.message,
      stack: record.error.stack,
      status: record.error.status || record.error.statusCode || 500
    }
  }
  ...
  logstash.send(record)
}

6.1.5 参考链接

上一节:5.2 Elastic APM

下一节:6.2 async_hooks

results matching ""

    No results matching ""