標籤：

Koa 請求日誌打點工具

01-28

前一段時間開始搞優化後端 API 性能的事，發現根本無從下手，Kibana 中雖然有記一些簡陋且零散的日誌，但也瞅不出啥眉目來。總結了下是日誌太少了，所以決定先搞搞日誌的事，目標是記錄 API 請求相關的日誌，找出哪個介面慢，最好具體到哪個函數慢。

記日誌必然要涉及日誌打點，怎麼做日誌打點是個問題。如果直接在代碼中插入日誌打點代碼不僅侵入性強而且工作量大，也不夠靈活，於是考慮如何做智能的自動打點。我們石墨後端使用的 bay 框架（基於 Koa@1 二次開發，基本上你可以認為就是用的 Koa@1），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 {n type: Program,n body:n [ Directive {n type: ExpressionStatement,n expression:n Literal {n type: Literal,n value: use strict,n raw: use strict,n loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 12 } } },n directive: use strict,n loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 13 } } },n VariableDeclaration {n type: VariableDeclaration,n declarations:n [ VariableDeclarator {n type: VariableDeclarator,n id:n Identifier {n type: Identifier,n name: Mongolass,n loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 15 } } },n init:n CallExpression {n type: CallExpression,n callee:n Identifier {n type: Identifier,n name: require,n loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 25 } } },n arguments:n [ Literal {n type: Literal,n value: mongolass,n raw: mongolass,n loc: { start: { line: 3, column: 26 }, end: { line: 3, column: 37 } } } ],n loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 38 } } },n loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 38 } } } ],n kind: const,n loc: { start: { line: 3, column: 0 }, end: { line: 3, column: 39 } } },n VariableDeclaration {n type: VariableDeclaration,n declarations:n [ VariableDeclarator {n type: VariableDeclarator,n id:n Identifier {n type: Identifier,n name: mongolass,n loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 15 } } },n init:n NewExpression {n type: NewExpression,n callee:n Identifier {n type: Identifier,n name: Mongolass,n loc: { start: { line: 4, column: 22 }, end: { line: 4, column: 31 } } },n arguments: [],n loc: { start: { line: 4, column: 18 }, end: { line: 4, column: 33 } } },n loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 33 } } } ],n kind: const,n loc: { start: { line: 4, column: 0 }, end: { line: 4, column: 34 } } },n ExpressionStatement {n type: ExpressionStatement,n expression:n CallExpression {n type: CallExpression,n callee:n StaticMemberExpression {n type: MemberExpression,n computed: false,n object:n Identifier {n type: Identifier,n name: mongolass,n loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 9 } } },n property:n Identifier {n type: Identifier,n name: connect,n loc: { start: { line: 5, column: 10 }, end: { line: 5, column: 17 } } },n loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 17 } } },n arguments:n [ Literal {n type: Literal,n value: mongodb://localhost:27017/test,n raw: mongodb://localhost:27017/test,n loc: { start: { line: 5, column: 18 }, end: { line: 5, column: 50 } } } ],n loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 51 } } },n loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 52 } } },n ExpressionStatement {n type: ExpressionStatement,n expression:n AssignmentExpression {n type: AssignmentExpression,n operator: =,n left:n StaticMemberExpression {n type: MemberExpression,n computed: false,n object:n Identifier {n type: Identifier,n name: exports,n loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 7 } } },n property:n Identifier {n type: Identifier,n name: getUsers,n loc: { start: { line: 7, column: 8 }, end: { line: 7, column: 16 } } },n loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 16 } } },n right:n FunctionExpression {n type: FunctionExpression,n id:n Identifier {n type: Identifier,n name: getUsers,n loc: { start: { line: 7, column: 29 }, end: { line: 7, column: 37 } } },n params: [],n body:n BlockStatement {n type: BlockStatement,n body:n [ ExpressionStatement {n type: ExpressionStatement,n expression:n YieldExpression {n type: YieldExpression,n argument:n CallExpression {n type: CallExpression,n callee:n StaticMemberExpression {n type: MemberExpression,n computed: false,n object: [Object],n property: [Object],n loc: [Object] },n arguments: [ [Object] ],n loc: { start: [Object], end: [Object] } },n delegate: false,n loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 4 } } },n loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 5 } } },n VariableDeclaration {n type: VariableDeclaration,n declarations:n [ VariableDeclarator {n type: VariableDeclarator,n id: Identifier { type: Identifier, name: users, loc: [Object] },n init:n YieldExpression {n type: YieldExpression,n argument: [Object],n delegate: false,n loc: [Object] },n loc: { start: [Object], end: [Object] } } ],n kind: const,n loc:n { start: { line: 13, column: 2 },n end: { line: 13, column: 54 } } },n ExpressionStatement {n type: ExpressionStatement,n expression:n AssignmentExpression {n type: AssignmentExpression,n operator: =,n left:n StaticMemberExpression {n type: MemberExpression,n computed: false,n object: ThisExpression { type: ThisExpression, loc: [Object] },n property: Identifier { type: Identifier, name: body, loc: [Object] },n loc: { start: [Object], end: [Object] } },n right:n Identifier {n type: Identifier,n name: users,n loc: { start: [Object], end: [Object] } },n loc:n { start: { line: 14, column: 2 },n end: { line: 14, column: 19 } } },n loc:n { start: { line: 14, column: 2 },n end: { line: 14, column: 20 } } } ],n loc: { start: { line: 7, column: 40 }, end: { line: 15, column: 1 } } },n generator: true,n expression: false,n loc: { start: { line: 7, column: 19 }, end: { line: 15, column: 1 } } },n loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 1 } } },n loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 2 } } } ],n sourceType: script,n loc: { start: { line: 1, column: 0 }, end: { line: 15, column: 2 } } }n相關源代碼如下：let parsedCodes;ntry {n parsedCodes = esprima.parse(content, { loc: true });n} catch (e) {n console.error(cannot parse file: %s, filename);n console.error(e.stack);n process.exit(1);n}n

  1. 遍歷找到 YieldExpression 節點，進行以下包裝後生成 AST 替換掉原來的節點。global.logger(

    this,

    function*(){

    return yield YieldExpression

    },

    YieldExpressionString,

    filename

    );

相關源代碼如下：findYieldAndWrapLogger(parsedCodes);ntry {n content = escodegen.generate(parsedCodes, {n format: { indent: { style: } },n sourceMap: filename,n sourceMapWithCode: truen });n} catch (e) {n console.error(cannot generate code for file: %s, filename);n console.error(e.stack);n process.exit(1);n}ndebug(file %s regenerate codes:n%s, filename, content.code);nfindYieldAndWrapLogger 作用就是遍歷 AST 將 YieldExpression 替換成用日誌函數包裹後新的 YieldExpression 的 AST。n

  1. 最後用 escodegen 將 AST 生成代碼（支持 soucemap，所以錯誤棧對應的行數是對的）。

核心：每個請求到來時，生成（項目中本來就有 requestId 的話，可通過配置指定）一個 requestId（uuid 類型）掛載到 this 上，這樣就可以通過 requestId 將日誌串起來了。

特點：可以記錄每個請求的流程（甚至可以查到某個用戶某個時間段的請求），及每一次請求的每一步（step）的現場及返回值，方便調試或查 bug，當然只針對 yield 表達式。

舉個栗子

app.js

use strict;nnconst koaYieldBreakpoint = require(koa-yield-breakpoint)({n files: [./routes/*.js]n});nnconst koa = require(koa);nconst routes = require(./routes);nconst app = koa();nnapp.use(koaYieldBreakpoint);nnroutes(app);nnapp.listen(3000, () => {n console.log(listening on 3000);n});n

routes/index.js

use strict;nnconst route = require(koa-route);nconst users = require(./users);nnmodule.exports = function (app) {n app.use(route.get(/users, users.getUsers));n};n

routes/users.js

use strict;nnconst Mongolass = require(mongolass);nconst mongolass = new Mongolass();nmongolass.connect(mongodb://localhost:27017/test);nnexports.getUsers = function* getUsers() {n yield mongolass.model(users).create({n name: xx,n age: 18n });nn const users = yield mongolass.model(users).find();n this.body = users;n};n

運行：

DEBUG=koa-yield-breakpoint node app.jsn

終端列印如下：

? example git:(master) DEBUG=koa-yield-breakpoint node app.jsnkoa-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"} +0msnnkoa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js"] +9msnnkoa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js regenerate codes:nuse strict;nconst route = require(koa-route);nconst users = require(./users);nmodule.exports = function (app) {n app.use(route.get(/users, users.getUsers));n}; +73msnnkoa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js regenerate codes:nuse strict;nconst Mongolass = require(mongolass);nconst mongolass = new Mongolass();nmongolass.connect(mongodb://localhost:27017/test);nexports.getUsers = function* getUsers() {n yield* global.logger(this, function* () {n return yield mongolass.model(users).create({n name: xx,n age: 18n });n }, mongolass.model(users).create({n name: xx,n age: 18n}), /Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2);n const users = yield* global.logger(this, function* () {n return yield mongolass.model(users).find();n }, mongolass.model(users).find(), /Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16);n this.body = users;n}; +15msnlistening on 3000n

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

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

為什麼要將 yield 表達式包裹成這樣呢？

global.logger(n this,n function*(){n return yield YieldExpressionn },n YieldExpressionString,n filenamen);n

而不是：

global.logger(n this,n function(){n return YieldExpressionn },n YieldExpressionString,n filenamen);n

或者：

global.logger(n this,n yield YieldExpression,n YieldExpressionString,n filenamen);n

因為考慮到 YieldExpression 可能是以下情況導致 esprima 不能解析：

  1. User.find(yield xxx)
  2. User.find(this.xxx)

所以綜合考慮只能放到 GeneratorFunction 里。

訪問 localhost:3000/users，終端列印出:

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

注意：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)({n files: [./controllers/*.js, ./middlewares/*.js],n store: require(./lib/koa_yield_breakpoint_logstash),n loggerName: __logger,n requestIdPath: header.reqid,n yieldCondition: (filename, yieldExpression) => {n // yield next 不包裹 loggern if (yieldExpression === next) {n return {n wrapYield: false,n deep: falsen };n }n if (yieldExpression.match(/^db.sequelize.transaction/)) {n return {n wrapYield: true,n deep: falsen };n }n }n});n...napp.use(koaYieldBreakpoint);n

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;nnconst co = require(co);nconst Mongolass = require(mongolass);nconst mongolass = new Mongolass();nmongolass.connect(mongodb://localhost:27017/test);nnco(function* () {n yield mongolass.model(users).create({n name: xx,n age: 18n });nn const users = yield mongolass.model(users).find();n console.log(users: %j, users);n}).catch(e => console.error(e.stack));n

終端列印如下：

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

真實用例：

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

koa-yield-breakpoint 自定義日誌欄位

store 參數最好自己定義（默認直接列印 log 到控制台），可以是一個 object 可以是一個實例，只需要有一個 save 方法即可。在 save 方法內可做一些自定義，比如我在 koa_yield_breakpoint_logstash.js 里添加了一些欄位（如：url, app, env），對錯誤請求日誌添加了一些欄位方便追蹤現場。如下：

use strict;nnconst _ = require(lodash);nnexports.save = function save(record, ctx) {n record.app = app name;n record.env = process.env.NODE_ENV;n if (ctx) {n record.url = ctx.method + + ctx.host + ctx.path;n }nn if (record.error) {n record.error = {n message: record.error.message,n stack: record.error.stack,n status: record.error.status || record.error.statusCode || 500n };n if (ctx && ctx.request) {n record.request = JSON.stringify(_.pick(ctx.request, url, method, headers, body, query, ips));n }n }n ...n};n

小心日誌打太多啦

在上線了 koa-yield-breakpoint + co-yield-breakpoint 這個組合後，就可以從 Kibana 查到某個 requestId 請求的每一步日誌了，但後來運維告訴我日誌打的太多了，於是加了個判斷：當請求發生錯誤或者請求結束時響應時間大於 500ms，則將這個請求的所有打點日誌記錄下來。最後代碼差不多是下面這個樣子：

use strict;nnconst _ = require(lodash);nconst logstashLogger = require(./logstash_logger);nnexports.save = function save(record, ctx) {n ctx.__koaYieldLogger = ctx.__koaYieldLogger || [];n record.app = api;n record.env = process.env.NODE_ENV;n if (ctx) {n record.url = ctx.method + + ctx.host + ctx.path;n if (ctx.routerName) {n record.routerName = ctx.routerName;n }n }nn if (record.error) {n record.error = {n message: record.error.message,n stack: record.error.stack,n status: record.error.status || record.error.statusCode || 500n };n if (ctx && ctx.request) {n record.request = JSON.stringify(_.pick(ctx.request, url, method, headers, body, query, ips));n }n }nn ctx.__koaYieldLogger.push(record);nn // 發生錯誤或者最後一步（並且響應時間大於 500ms）才會發送到 logstashn if (record.error || (record.status === end)) {n const sumOfTake = _.sumBy(ctx.__koaYieldLogger, take);n if (record.error || sumOfTake > 500) {n // end|error 即最後一條 log 添加一個 sumOfTake 欄位記錄這個請求的總響應時間n record.sumOfTake = sumOfTake;n // 發送多條 log，而不是合成一條，方便在 kibana 聚合n ctx.__koaYieldLogger.forEach(function (record) {n logstashLogger.info(record);n });n }n }n};n

最後

我們正在招聘！

[北京/武漢] 石墨文檔 做最美產品 - 尋找中國最有才華的工程師加入

推薦閱讀：

※為什麼Node的web端框架express和Koa的生態環境差距還是巨大（2017.11）？

TAG:Nodejs | koa | 日志 |