Skip to content

Latest commit

 

History

History
286 lines (241 loc) · 10.7 KB

6.1 koa-await-breakpoint.md

File metadata and controls

286 lines (241 loc) · 10.7 KB

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