日志打点一直是个调试最头疼的问题。如果直接在代码中插入埋点代码，不仅侵入性强而且工作量大也不够灵活，要是能做到智能打点就好了，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。

使用方法如下：

  1. // On top of the main file
  2. const koaAwaitBreakpoint = require('koa-await-breakpoint')({
  3.   name: 'api',
  4.   files: ['./routes/*.js']
  5. })
  7. const Koa = require('koa')
  8. const app = new Koa()
  10. // Generally, above other middlewares
  11. app.use(koaAwaitBreakpoint)
  12. ...
  14. app.listen(3000)

6.1.2 实现原理

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

    1. shimmer.wrap(Module.prototype, '_compile', function (__compile) {
    2.  return function koaBreakpointCompile(content, filename) {
    3.    if (!_.includes(filenames, filename)) {
    4.      return __compile.call(this, content, filename);
    5.    }
    6.    ...
    7.  };
    8. });

  2. 用 esprima 解析代码，生成 AST。例如：

    1. const Mongolass = require('mongolass')
    2. const mongolass = new Mongolass('mongodb://localhost:27017/test')
    3. const User = mongolass.model('users')
    5. exports.getUsers = async function getUsers(ctx) {
    6.  await User.create({
    7.    name: 'xx',
    8.    age: 18
    9.  })
    10.  const users = await User.find()
    11.  return users
    12. }

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

    1. Script {
    2.  ...
    3.  AwaitExpression {
    4.    type: 'AwaitExpression',
    5.    argument:
    6.     CallExpression {
    7.       type: 'CallExpression',
    8.       callee:
    9.        StaticMemberExpression {
    10.          type: 'MemberExpression',
    11.          computed: false,
    12.          object:
    13.           Identifier {
    14.             type: 'Identifier',
    15.             name: 'User',
    16.             loc: { start: { line: 6, column: 10 }, end: { line: 6, column: 14 } } },
    17.          property:
    18.           Identifier {
    19.             type: 'Identifier',
    20.             name: 'create',
    21.             loc: { start: { line: 6, column: 15 }, end: { line: 6, column: 21 } } },
    22.          loc: { start: { line: 6, column: 10 }, end: { line: 6, column: 21 } } },
    23.       arguments:
    24.        [ ObjectExpression {
    25.            type: 'ObjectExpression',
    26.            properties:
    27.             [ Property {
    28.                 type: 'Property',
    29.                 key:
    30.                  Identifier {
    31.                    type: 'Identifier',
    32.                    name: 'name',
    33.                    loc: { start: { line: 7, column: 6 }, end: { line: 7, column: 10 } } },
    34.                 computed: false,
    35.                 value:
    36.                  Literal {
    37.                    type: 'Literal',
    38.                    value: 'xx',
    39.                    raw: '\'xx\'',
    40.                    loc: { start: { line: 7, column: 12 }, end: { line: 7, column: 16 } } },
    41.                 kind: 'init',
    42.                 method: false,
    43.                 shorthand: false,
    44.                 loc: { start: { line: 7, column: 6 }, end: { line: 7, column: 16 } } },
    45.               Property {
    46.                 type: 'Property',
    47.                 key:
    48.                  Identifier {
    49.                    type: 'Identifier',
    50.                    name: 'age',
    51.                    loc: { start: { line: 8, column: 6 }, end: { line: 8, column: 9 } } },
    52.                 computed: false,
    53.                 value:
    54.                  Literal {
    55.                    type: 'Literal',
    56.                    value: 18,
    57.                    raw: '18',
    58.                    loc: { start: { line: 8, column: 11 }, end: { line: 8, column: 13 } } },
    59.                 kind: 'init',
    60.                 method: false,
    61.                 shorthand: false,
    62.                 loc: { start: { line: 8, column: 6 }, end: { line: 8, column: 13 } } } ],
    63.            loc: { start: { line: 6, column: 22 }, end: { line: 9, column: 5 } } } ],
    64.       loc: { start: { line: 6, column: 10 }, end: { line: 9, column: 6 } } },
    65.    loc: { start: { line: 6, column: 4 }, end: { line: 9, column: 6 } } },
    66.  ...

  3. 遍历找到 awaitExpression 节点，进行以下包装后生成 AST，替换掉原来的节点。

    1. global.logger(
    2.  (typeof ctx !== 'undefined' ? ctx : this),
    3.  function(){
    4.    return awaitExpression
    5.  },
    6.  awaitExpressionString,
    7.  filename
    8. )

    相关源代码如下：

    1. findAwaitAndWrapLogger(parsedCodes)
    2. try {
    3.  content = escodegen.generate(parsedCodes, {
    4.    format: { indent: { style: '  ' } },
    5.    sourceMap: filename,
    6.    sourceMapWithCode: true
    7.  })
    8. } catch (e) {
    9.  console.error('cannot generate code for file: %s', filename)
    10.  console.error(e.stack)
    11.  process.exit(1)
    12. }
    13. 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

  1. const koaAwaitBreakpoint = require('koa-await-breakpoint')({
  2.   name: 'api',
  3.   files: ['./routes/*.js']
  4. })
  6. const Paloma = require('paloma')
  7. const app = new Paloma()
  8. const userRouter = require('./routes/user')
  10. app.use(koaAwaitBreakpoint)
  11. app.route({ method: 'GET', path: '/users', controller: userRouter.getUsers })
  13. app.listen(3000)

routes/user.js

  1. const Mongolass = require('mongolass')
  2. const mongolass = new Mongolass('mongodb://localhost:27017/test')
  3. const User = mongolass.model('users')
  5. exports.getUsers = async function getUsers (ctx) {
  6.   await User.create({
  7.     name: 'xx',
  8.     age: 18
  9.   })
  11.   const users = await User.find()
  12.   ctx.body = users
  13. }

运行：

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

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

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

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

  1. {"name":"api","requestId":"50dbda0c-9e13-4659-acce-b237bc5178b7","timestamp":"2018-02-26T06:31:31.100Z","this":...,"type":"start","step":1,"take":0}
  2. {"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}
  3. {"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}
  4. {"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}
  5. {"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}
  6. {"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

  1. exports.save = function save(record, ctx) {
  2.   record.name = 'app name'
  3.   record.env = process.env.NODE_ENV
  5.   if (record.error) {
  6.     record.error = {
  7.       message: record.error.message,
  8.       stack: record.error.stack,
  9.       status: record.error.status || record.error.statusCode || 500
  10.     }
  11.   }
  12.   ...
  13.   logstash.send(record)
  14. }

6.1.5 参考链接

上一节：5.2 Elastic APM

下一节：6.2 async_hooks