Koa 请求日志打点工具

前一段时间开始搞优化后端 API 性能的事，发现根本无从下手，Kibana 中虽然有记一些简陋且零散的日志，但也瞅不出啥眉目来。总结了下是日志太少了，所以决定先搞搞日志的事，目标是记录 API 请求相关的日志，找出哪个接口慢，最好具体到哪个函数慢。

记日志必然要涉及日志打点，怎么做日志打点是个问题。如果直接在代码中插入日志打点代码不仅侵入性强而且工作量大，也不够灵活，于是考虑如何做智能的自动打点。我们石墨后端使用的 bay 框架（基于 Koa@1 二次开发，基本上你可以认为就是用的 Koa），controller 里用了大量的 yield，所以考虑是不是可以在 yield 表达式前后打点，调研了下觉得可以用 esprima 和 escodegen 做。

奋战几天，koa-yield-breakpoint 诞生了。

koa-yield-breakpoint

koa-yield-breakpoint 就是一个在 controllers 或者 routes 里的 yield 表达式前后打点的工具，不用插入一行日志打点代码，只需要在引入的时候配置一下，可以记录每个请求到来时 yield 表达式前后的现场，如：

1. yield 表达式所在的行列号（filename）
   

2. yield 表达式是执行的第几步（step）

3. yield 表达式字符串形式（fn）
   

4. 执行 yield 表达式所花费的时间（take）

5. 执行 yield 表达式的结果（result）
   

6. yield 表达式当时的现场（this），通过 this 你也可以添加自定义字段

原理：

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。如：

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

   会生成如下 AST：

   Program {  type: 'Program',  body:   [ Directive {       type: 'ExpressionStatement',       expression:        Literal {          type: 'Literal',          value: 'use strict',          raw: '\'use strict\'',          loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 12 } } },       directive: 'use strict',       loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 13 } } },     VariableDeclaration {       type: 'VariableDeclaration',       declarations:        [ VariableDeclarator {            type: 'VariableDeclarator',            id:             Identifier {               type: 'Identifier',               name: 'Mongolass',               loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 15 } } },            init:             CallExpression {               type: 'CallExpression',               callee:                Identifier {                  type: 'Identifier',                  name: 'require',                  loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 25 } } },               arguments:                [ Literal {                    type: 'Literal',                    value: 'mongolass',                    raw: '\'mongolass\'',                    loc: { start: { line: 3, column: 26 }, end: { line: 3, column: 37 } } } ],               loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 38 } } },            loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 38 } } } ],       kind: 'const',       loc: { start: { line: 3, column: 0 }, end: { line: 3, column: 39 } } },     VariableDeclaration {       type: 'VariableDeclaration',       declarations:        [ VariableDeclarator {            type: 'VariableDeclarator',            id:             Identifier {               type: 'Identifier',               name: 'mongolass',               loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 15 } } },            init:             NewExpression {               type: 'NewExpression',               callee:                Identifier {                  type: 'Identifier',                  name: 'Mongolass',                  loc: { start: { line: 4, column: 22 }, end: { line: 4, column: 31 } } },               arguments: [],               loc: { start: { line: 4, column: 18 }, end: { line: 4, column: 33 } } },            loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 33 } } } ],       kind: 'const',       loc: { start: { line: 4, column: 0 }, end: { line: 4, column: 34 } } },     ExpressionStatement {       type: 'ExpressionStatement',       expression:        CallExpression {          type: 'CallExpression',          callee:           StaticMemberExpression {             type: 'MemberExpression',             computed: false,             object:              Identifier {                type: 'Identifier',                name: 'mongolass',                loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 9 } } },             property:              Identifier {                type: 'Identifier',                name: 'connect',                loc: { start: { line: 5, column: 10 }, end: { line: 5, column: 17 } } },             loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 17 } } },          arguments:           [ Literal {               type: 'Literal',               value: 'mongodb://localhost:27017/test',               raw: '\'mongodb://localhost:27017/test\'',               loc: { start: { line: 5, column: 18 }, end: { line: 5, column: 50 } } } ],          loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 51 } } },       loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 52 } } },     ExpressionStatement {       type: 'ExpressionStatement',       expression:        AssignmentExpression {          type: 'AssignmentExpression',          operator: '=',          left:           StaticMemberExpression {             type: 'MemberExpression',             computed: false,             object:              Identifier {                type: 'Identifier',                name: 'exports',                loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 7 } } },             property:              Identifier {                type: 'Identifier',                name: 'getUsers',                loc: { start: { line: 7, column: 8 }, end: { line: 7, column: 16 } } },             loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 16 } } },          right:           FunctionExpression {             type: 'FunctionExpression',             id:              Identifier {                type: 'Identifier',                name: 'getUsers',                loc: { start: { line: 7, column: 29 }, end: { line: 7, column: 37 } } },             params: [],             body:              BlockStatement {                type: 'BlockStatement',                body:                 [ ExpressionStatement {                     type: 'ExpressionStatement',                     expression:                      YieldExpression {                        type: 'YieldExpression',                        argument:                         CallExpression {                           type: 'CallExpression',                           callee:                            StaticMemberExpression {                              type: 'MemberExpression',                              computed: false,                              object: [Object],                              property: [Object],                              loc: [Object] },                           arguments: [ [Object] ],                           loc: { start: [Object], end: [Object] } },                        delegate: false,                        loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 4 } } },                     loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 5 } } },                   VariableDeclaration {                     type: 'VariableDeclaration',                     declarations:                      [ VariableDeclarator {                          type: 'VariableDeclarator',                          id: Identifier { type: 'Identifier', name: 'users', loc: [Object] },                          init:                           YieldExpression {                             type: 'YieldExpression',                             argument: [Object],                             delegate: false,                             loc: [Object] },                          loc: { start: [Object], end: [Object] } } ],                     kind: 'const',                     loc:                      { start: { line: 13, column: 2 },                        end: { line: 13, column: 54 } } },                   ExpressionStatement {                     type: 'ExpressionStatement',                     expression:                      AssignmentExpression {                        type: 'AssignmentExpression',                        operator: '=',                        left:                         StaticMemberExpression {                           type: 'MemberExpression',                           computed: false,                           object: ThisExpression { type: 'ThisExpression', loc: [Object] },                           property: Identifier { type: 'Identifier', name: 'body', loc: [Object] },                           loc: { start: [Object], end: [Object] } },                        right:                         Identifier {                           type: 'Identifier',                           name: 'users',                           loc: { start: [Object], end: [Object] } },                        loc:                         { start: { line: 14, column: 2 },                           end: { line: 14, column: 19 } } },                     loc:                      { start: { line: 14, column: 2 },                        end: { line: 14, column: 20 } } } ],                loc: { start: { line: 7, column: 40 }, end: { line: 15, column: 1 } } },             generator: true,             expression: false,             loc: { start: { line: 7, column: 19 }, end: { line: 15, column: 1 } } },          loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 1 } } },       loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 2 } } } ],  sourceType: 'script',  loc: { start: { line: 1, column: 0 }, end: { line: 15, column: 2 } } }

   相关源代码如下：

   let parsedCodes;try {  parsedCodes = esprima.parse(content, { loc: true });} catch (e) {  console.error('cannot parse file: %s', filename);  console.error(e.stack);  process.exit(1);}

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

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

   相关源代码如下：

   findYieldAndWrapLogger(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);

   findYieldAndWrapLogger 作用就是遍历 AST 将 YieldExpression 替换成用日志函数包裹后新的 YieldExpression 的 AST。

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.jskoa-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"} +0mskoa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js"] +9mskoa-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));}; +73mskoa-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;}; +15mslistening 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% 的请求日志，但这种方案是：这个请求的所有日志要么都记，要么都不记（错误日志除外，错误日志一定记）。

最后

我们正在招聘！

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