Koa 请求日志打点工具（下篇）

4 、最后用 escodegen 将 AST 生成代码（支持 soucemap ，所以错误栈对应的行数是对的）。核心：每个请求到来时，生成（项目中本来就有 requestId 的话，可通过配置指定）一个 requestId （ uuid 类型）挂载到 this 上，这样就可以通过 requestId 将日志串起来了。

特点：可以记录每个请求的流程（甚至可以查到某个用户某个时间段的请求），及每一次请求的每一步（ step ）的现场及返回值，方便调试或查 bug ，当然只针对 yield 表达式。

举个栗子

app.js

'use strict';

const koaYieldBreakpoint = require('koa-yield-breakpoint')({
  files: ['./routes/*.js']
});

const koa = require('koa');
const routes = require('./routes');
const app = koa();

app.use(koaYieldBreakpoint);

routes(app);

app.listen(3000, () => {
  console.log('listening on 3000');
});

routes/index.js

'use strict';

const route = require('koa-route');
const users = require('./users');

module.exports = function (app) {
  app.use(route.get('/users', users.getUsers));
};

routes/users.js

'use strict';

const Mongolass = require('mongolass');
const mongolass = new Mongolass();
mongolass.connect('mongodb://localhost:27017/test');

exports.getUsers = function* getUsers() {
  yield mongolass.model('users').create({
    name: 'xx',
    age: 18
  });

  const users = yield mongolass.model('users').find();
  this.body = users;
};

运行：

DEBUG=koa-yield-breakpoint node app.js

终端打印如下：

➜  example git:(master) DEBUG=koa-yield-breakpoint node app.js
koa-yield-breakpoint options: {"files":["./routes/*.js"],"nodir":true,"absolute":true,"filter":{"ctx":["state","params"],"request":["method","path","header","query","body"],"response":["status","body"]},"loggerName":"logger","requestIdPath":"requestId"} +0ms

koa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js"] +9ms

koa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js regenerate codes:
'use strict';
const route = require('koa-route');
const users = require('./users');
module.exports = function (app) {
  app.use(route.get('/users', users.getUsers));
}; +73ms

koa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js regenerate codes:
'use strict';
const Mongolass = require('mongolass');
const mongolass = new Mongolass();
mongolass.connect('mongodb://localhost:27017/test');
exports.getUsers = function* getUsers() {
  yield global.logger(this, function* () {
    return mongolass.model('users').create({
      name: 'xx',
      age: 18
    });
  }, 'mongolass.model(\'users\').create({\n    name: \'xx\',\n    age: 18\n})', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2');
  const users = yield global.logger(this, function* () {
    return mongolass.model('users').find();
  }, 'mongolass.model(\'users\').find()', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16');
  this.body = users;
}; +15ms
listening on 3000

可以看出， routes/users.js 被替换成了：

'use strict';
const Mongolass = require('mongolass');
const mongolass = new Mongolass();
mongolass.connect('mongodb://localhost:27017/test');
exports.getUsers = function* getUsers() {
  yield global.logger(this, function* () {
    return mongolass.model('users').create({
      name: 'xx',
      age: 18
    });
  }, 'mongolass.model(\'users\').create({\n    name: \'xx\',\n    age: 18\n})', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2');
  const users = yield global.logger(this, function* () {
    return mongolass.model('users').find();
  }, 'mongolass.model(\'users\').find()', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16');
  this.body = users;
};

为什么要将 yield 表达式包裹成这样呢？

global.logger(
  this,
  function*(){
    return YieldExpression
  },
  YieldExpressionString,
  filename
);

而不是：

global.logger(
  this,
  function(){
    return YieldExpression
  },
  YieldExpressionString,
  filename
);

或者：

global.logger(
  this,
  yield YieldExpression,
  YieldExpressionString,
  filename
);

因为考虑到 YieldExpression 可能是以下情况导致 esprima 不能解析：

1 、 User.find(yield xxx) 2 、 User.find( http://this.xxx)

所以综合考虑只能放到 GeneratorFunction 里，另外，不用：

global.logger(
  this,
  function*(){
    return yield YieldExpression
  },
  YieldExpressionString,
  filename
);

是因为这样会导致 esprima 解析死循环，所以去掉了里面的 yield ，在 logger 里 yield 。

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

{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 404, body: undefined } },
  type: 'start',
  step: 1,
  take: 0 }
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  step: 2,
  filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 404, body: undefined } },
  type: 'before',
  fn: 'mongolass.model(\'users\').create({\n    name: \'xx\',\n    age: 18\n})',
  result: undefined,
  take: 1 }
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  step: 3,
  filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 404, body: undefined } },
  type: 'after',
  fn: 'mongolass.model(\'users\').create({\n    name: \'xx\',\n    age: 18\n})',
  result:
   { result: { ok: 1, n: 1 },
     ops: [ [Object] ],
     insertedCount: 1,
     insertedIds: [ undefined, 5810856182d0eea2f12030fd ] },
  take: 7 }
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  step: 4,
  filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 404, body: undefined } },
  type: 'before',
  fn: 'mongolass.model(\'users\').find()',
  result: undefined,
  take: 1 }
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  step: 5,
  filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 404, body: undefined } },
  type: 'after',
  fn: 'mongolass.model(\'users\').find()',
  result: [ { _id: 5810856182d0eea2f12030fd, name: 'xx', age: 18 } ],
  take: 4 }
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
  timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
  this:
   { state: {},
     request:
      { method: 'GET',
        path: '/users',
        header: [Object],
        query: [Object] },
     response: { status: 200, body: [Object] } },
  type: 'end',
  step: 6,
  take: 1 }

注意： type 是 ['start', 'beforeYield', 'afterYield', 'error', 'end'] 其中一种， take 单位是 ms 。

1 、 start: 请求到来时第一次打点 2 、 beforeYield: 上一个 yieldExpression 之后到这一个 yieldExpression 之前 3 、 afterYield: 这个 yieldExpression 开始到结束 4 、 error: 错误日志， koa-yield-breakpoint 会记录下来，然后再 throw 出去 5 、 end: 请求结束时打点

真实用例

const koaYieldBreakpoint = require('koa-yield-breakpoint')({
  files: ['./controllers/*.js', './middlewares/*.js'],
  store: require('./lib/koa_yield_breakpoint_logstash'),
  loggerName: '__logger',
  requestIdPath: 'header.reqid',
  yieldCondition: (filename, yieldExpression) => {
    // yield next 不包裹 logger
    if (yieldExpression === 'next') {
      return {
        wrapYield: false,
        deep: false
      };
    }
    if (yieldExpression.match(/^db\.sequelize\.transaction/)) {
      return {
        wrapYield: true,
        deep: false
      };
    }
  }
});
...
app.use(koaYieldBreakpoint);

co-yield-breakpoint

koa-yield-breakpoint 主要用在 Koa 的 routes 、 controllers 或 middlewares 文件。 co-yield-breakpoint 主要用来给普通 yield 表达式（如 lib 或 models 下的文件）打点（没有 requestId ，所以 log 是零散的，这里只用来计算平均耗时），实现原理跟 koa-yield-breakpoint 类似，这里不再赘述。

foo.js

'use strict';

const co = require('co');
const Mongolass = require('mongolass');
const mongolass = new Mongolass();
mongolass.connect('mongodb://localhost:27017/test');

co(function* () {
  yield mongolass.model('users').create({
    name: 'xx',
    age: 18
  });

  const users = yield mongolass.model('users').find();
  console.log('users: %j', users);
}).catch(e => console.error(e.stack));

终端打印如下：

{
  "filename": "/Users/nswbmw/node/co-yield-breakpoint/example/foo.js:9:2",
  "timestamp": "2016-11-10T13:53:33.053Z",
  "fn": "mongolass.model('users').create({\n    name: 'xx',\n    age: 18\n})",
  "result": {
    "result": {
      "ok": 1,
      "n": 1
    },
    "ops": [{
      "name": "xx",
      "age": 18,
      "_id": "58247bdd3fb205dbad5418a0"
    }],
    "insertedCount": 1,
    "insertedIds": [null, "58247bdd3fb205dbad5418a0"]
  },
  "take": 55
}
{
  "filename": "/Users/nswbmw/node/co-yield-breakpoint/example/foo.js:14:16",
  "timestamp": "2016-11-10T13:53:33.060Z",
  "fn": "mongolass.model('users').find()",
  "result": [{
    "_id": "58247bdd3fb205dbad5418a0",
    "name": "xx",
    "age": 18
  }],
  "take": 7
}
users: [{
  "_id": "58247bdd3fb205dbad5418a0",
  "name": "xx",
  "age": 18
}]

真实用例：

require('co-yield-breakpoint')({
  files: ['./lib/**/*.js', './models/**/*.js'],
  store: require('./lib/koa_yield_breakpoint_logstash'),
  loggerName: '__coLogger'
});

koa-yield-breakpoint 其他用法

store 参数最好自己定义，可以是一个 object 可以是一个实例，只需要有一个 save 方法即可。在 save 方法内可做一些自定义，比如我在 koa-yield_breakpoint_logstash.js 里添加了一些字段（如： url ），同时对正常请求日志过滤了一些字段，对错误请求日志添加了一些字段方便 bug 追踪。如下：

if (ctx.request) {
  record.request = _.pick(ctx.request, 'headers', 'body', 'query', 'ips');
}

小心日志打太多啦

线上 API 在上了 koa-yield-breakpoint + co-yield-breakpoint 这个组合后，我又让运维在 Kibana 作了以下 3 种图表：

1 、 fn 的平均耗时，由高到低（根据 filename 聚合, 因为 filename 中包含行列数，唯一） 2 、每个接口的平均耗时，由高到低（根据 url 聚合） 3 、所有 requestId 耗时排行（对应这个 requestId 所有日志 take 值累加），由高到低

看起来效果良好，但后来运维告诉我日志打的太多了，想想也是，一个逻辑复杂的 api 的请求从开始到结束，可能执行了几十次 yield 。。讨论了下，决定只采样 10% 日志。如下：

exports.save = function save(record, ctx) {
  ...
  if (Math.random() > 0.1 && !record.error) {// co-yield-breakpoint 的 record.error 总为 undefined
    return;
  }
  ...
};

注意：这里 koa-yield-breakpoint 和 co-yield-breakpoint 的日志都随机取样了 10%， co-yield-breakpoint 的日志倒无所谓，但 koa-yield-breakpoint 的日志则被打散了，也就是说你基本上不可能通过一个 requestId 查到完整的请求日志链了（ step 是连续的）。另一种方案是在 koa-yield-breakpoint 中间件之前给 this 添加一个属性：

function *(next) {
  this.shouldSaveLog = Math.random() < 0.1;
  yield next;
};

然后再 save 方法内判断一下 shouldSaveLog 决定是否记录这条日志，上面代码改为：

exports.save = function save(record, ctx) {
  ...
  if (!ctx.shouldSaveLog && !record.error) {
    return;
  }
  ...
};

这样也实现了只记录 10% 的请求日志，但这种方案是：这个请求的所有日志要么都记，要么都不记（错误日志除外，错误日志一定记）。

最后

我们正在招聘！

北京 /武汉石墨文档做最美产品 - 寻找中国最有才华的工程师加入