feat: add basic perf time, udpate fastify version, support log.addFie…

…ld, better fatal log
searchfe · Dec 1, 2022 · c617681 · c617681
1 parent c78308d
commit c617681
Show file tree

Hide file tree

Showing 21 changed files with 207 additions and 70 deletions.
diff --git a/README.md b/README.md
@@ -50,29 +50,30 @@ npm run dev
 
 ### Preparation
 ```sh
-npm i lerna -g
-
+npm i lerna -g --registry https://registry.npmmirror.com
 lerna bootstrap --registry https://registry.npmmirror.com
 lerna link
-
-# global link
-cd packages/cli
-npm link
 ```
 
 ### Cli development
 ```sh
-# watch @hoth/cli
+# add npm package
+lerna add config-enhanced --scope @hoth/app-autoload --registry https://registry.npmmirror.com
+
+# watch packages
 lerna exec "tsc --build -w tsconfig.json" --scope @hoth/cli
 lerna exec "tsc --build -w tsconfig.json" --scope @hoth/decorators
 lerna exec "tsc --build -w tsconfig.json" --scope @hoth/app-autoload
 lerna exec "tsc --build -w tsconfig.json" --scope @hoth/logger
 
-lerna add config-enhanced --scope @hoth/app-autoload --registry https://registry.npmmirror.com
-
-# debug for "hoth start"
+# debug for example
 cd example/hoth-quickstart
-npm link @hoth/cli
+npm i --registry https://registry.npmmirror.com
 npm run dev
+
+# unit test fro a package
+npm run test packages/logger
+npm run test packages/cli
+npm run test packages/app-autoload
 ```
 
diff --git a/example/hoth-quickstart/nodemon.json b/example/hoth-quickstart/nodemon.json
@@ -1,7 +1,7 @@
 {
-    "watch": ["*.ts", "*.tpl"],
+    "watch": ["*.ts", "src/*.tpl"],
     "ignore": ["*.test.ts", "node_modules/*", "*.d.ts"],
     "ext": "ts,js,tpl",
-    "exec": "npm run build && NODE_ENV=development hoth start --app-dir='dist' --app-name='hoth-quickstart' --app-prefix='/hoth-quickstart'",
+    "exec": "npm run build && NODE_ENV=development node ../../node_modules/.bin/hoth start --app-dir='dist' --app-name='hoth-quickstart' --app-prefix='/hoth-quickstart'",
     "legacyWatch": true
 }
diff --git a/example/hoth-quickstart/src/controller/index/index.controller.ts b/example/hoth-quickstart/src/controller/index/index.controller.ts
@@ -1,6 +1,6 @@
 import {Controller, GET, Inject} from '@hoth/decorators';
 import type {FastifyReply, FastifyRequest} from 'fastify';
-import Calculator from '../../lib/calc/index.service'
+import Calculator from '../../lib/calc/index.service';
 
 @Controller('/index')
 export default class AppController {
@@ -10,6 +10,17 @@ export default class AppController {
 
     @GET()
     getApp(req: FastifyRequest, reply: FastifyReply) {
+        // test for log
+        // try {
+        //     (reply as any).sss('aa');
+        // }
+        // catch (e) {
+        //     req.log.addNotice('type', 'black');
+        //     req.log.addField('os', 'ios');
+        //     req.log.fatal(e);
+        //     req.log.fatal(e, 'handle error');
+        //     req.log.fatal({req, from: 'home'}, 'handle error');
+        // }
         reply.view('index.tpl', {
             name: req.$appConfig.get('name'),
             foo: req.$appConfig.get('foo'),

diff --git a/packages/app-autoload/__tests__/basic.spec.ts b/packages/app-autoload/__tests__/basic.spec.ts
@@ -18,6 +18,7 @@ describe('@hoth/app-autoload basic app', () => {
         trace: noop,
         notice: noop,
         // @ts-ignore
+        addField: noop,
         addNotice: noop,
         addPerformance: noop,
         child: () => logger,

diff --git a/packages/app-autoload/__tests__/multi.spec.ts b/packages/app-autoload/__tests__/multi.spec.ts
@@ -1,10 +1,9 @@
-import Fastify, {FastifyInstance, FastifyLoggerInstance} from 'fastify';
+import fastifyFactory, {FastifyInstance, FastifyLoggerInstance} from 'fastify';
 import {resolve} from 'path';
 import appAutoload, {AppConfig, getApps} from '../src/index';
 
 describe('@hoth/app-autoload multi app', () => {
-
-    function noop () {}
+    function noop() {}
     let apps: AppConfig[];
     let fastify: FastifyInstance;
     let logger: FastifyLoggerInstance = {
@@ -15,6 +14,7 @@ describe('@hoth/app-autoload multi app', () => {
         debug: noop,
         trace: noop,
         notice: noop,
+        addField: noop,
         addNotice: noop,
         addPerformance: noop,
         child: () => logger,
@@ -28,7 +28,7 @@ describe('@hoth/app-autoload multi app', () => {
             prefix: '/',
         });
 
-        fastify = Fastify({
+        fastify = fastifyFactory({
             disableRequestLogging: true,
             logger,
         });

diff --git a/packages/app-autoload/src/hook/onRequestFactory.ts b/packages/app-autoload/src/hook/onRequestFactory.ts
@@ -2,11 +2,11 @@ import {performance} from 'perf_hooks';
 import {FastifyInstance, FastifyRequest} from 'fastify';
 import uuid from 'uuid-random';
 
-export const parseStartTimeSym = Symbol.for('hoth.parse-start-time');
+export const reqStartTimeSym = Symbol.for('hoth.req-start-time');
 
 export default function (appConfig: FastifyRequest['$appConfig'], fastify: FastifyInstance) {
     return async function (req: FastifyRequest) {
-        req[parseStartTimeSym] = performance.now();
+        req[reqStartTimeSym] = performance.now();
         req.logid = req.logid
             || (req.headers.x_bd_logid as string)
             || (req.headers.logid as string)

diff --git a/packages/app-autoload/src/hook/onResponse.ts b/packages/app-autoload/src/hook/onResponse.ts
@@ -0,0 +1,47 @@
+import {performance} from 'perf_hooks';
+import {FastifyReply, FastifyRequest} from 'fastify';
+import {reqStartTimeSym} from './onRequestFactory';
+import {parseStartTimeSym} from './preParsing';
+import {validateStartTimeSym} from './preValidation';
+import {handlerStartTimeSym} from './preHandlerFactory';
+import {serializationTimeSym} from './preSerialization';
+import {sendStartTimeSym} from './onSend';
+
+declare module 'fastify' {
+    interface FastifyLoggerInstance {
+        notice: (...args: any[]) => void;
+    }
+
+    interface FastifyRequest {
+        [reqStartTimeSym]: number;
+        [parseStartTimeSym]: number;
+        [validateStartTimeSym]: number;
+        [handlerStartTimeSym]: number;
+        [serializationTimeSym]: number;
+        [sendStartTimeSym]: number;
+    }
+}
+
+// Attention: https://www.fastify.io/docs/v3.19.x/Server/#disablerequestlogging
+// 因为禁用disablerequestlogging，onResponse Hook的报错，会被吞掉
+export default async function (req: FastifyRequest, reply: FastifyReply) {
+    const now = performance.now();
+    // 非post，不会执行preParse hook
+    const parseStartTime = req[parseStartTimeSym] || req[reqStartTimeSym];
+    // text响应不会执行preSerialization hook
+    const serializationStartTime = req[serializationTimeSym] || req[sendStartTimeSym];
+
+    req.log.addNotice('initTime', (parseStartTime - req[reqStartTimeSym]).toFixed(1));
+    req.log.addNotice('parseTime', (req[validateStartTimeSym] - parseStartTime).toFixed(1));
+    req.log.addNotice('validateTime', (req[handlerStartTimeSym] - req[validateStartTimeSym]).toFixed(1));
+    req.log.addNotice('handleTime', (serializationStartTime - req[handlerStartTimeSym]).toFixed(1));
+    req.log.addNotice('serialTime', (req[sendStartTimeSym] - serializationStartTime).toFixed(1));
+    req.log.addNotice('sendTime', (now - req[sendStartTimeSym]).toFixed(1));
+
+    reply.log.notice({
+        req,
+        res: reply,
+        responseTime: reply.getResponseTime().toFixed(1),
+    }, 'request completed');
+}
+
diff --git a/packages/app-autoload/src/hook/onSend.ts b/packages/app-autoload/src/hook/onSend.ts
@@ -1,18 +1,11 @@
 import {FastifyReply, FastifyRequest} from 'fastify';
+import {performance} from 'perf_hooks';
 
-declare module 'fastify' {
-    interface FastifyLoggerInstance {
-        notice: (...args: any[]) => void;
-    }
-}
+export const sendStartTimeSym = Symbol.for('hoth.send-start-time');
 
 export default async function (req: FastifyRequest, reply: FastifyReply) {
-    const responseTime = reply.getResponseTime();
-    reply.log.notice({
-        req,
-        res: reply,
-        responseTime: responseTime.toFixed(1),
-    }, 'request completed');
-    reply.header('X-Response-Time', responseTime);
+    const resTime = reply.getResponseTime();
+    req[sendStartTimeSym] = performance.now();
+    reply.header('X-Response-Time', resTime);
     reply.removeHeader('X-Powered-By');
 }
diff --git a/packages/app-autoload/src/hook/preHandlerFactory.ts b/packages/app-autoload/src/hook/preHandlerFactory.ts
@@ -1,19 +1,51 @@
 import {FastifyReply, FastifyRequest} from 'fastify';
 import {performance} from 'perf_hooks';
-import {parseStartTimeSym} from './onRequestFactory';
-import {validateStartTimeSym} from './preValidation';
 
-declare module 'fastify' {
-    interface FastifyRequest {
-        [validateStartTimeSym]: number;
-        [parseStartTimeSym]: number;
-    }
-}
+export const handlerStartTimeSym = Symbol.for('hoth.handler-start-time');
 
 export default function (app: string) {
     return async function (req: FastifyRequest, reply: FastifyReply) {
+        req[handlerStartTimeSym] = performance.now();
         req.log = reply.log = reply.log.child({req, app});
-        req.log.addNotice('parseTime', (req[validateStartTimeSym] - req[parseStartTimeSym]).toFixed(1));
-        req.log.addNotice('validationTime', (performance.now() - req[validateStartTimeSym]).toFixed(1));
+
+        // 业务需要 req.log.fatal({req, err}, 'msg'); 才能触发serializers对应的req序列化，才能在fatal里拿到notices信息
+        // 为了简化成 req.log.fatal(err) 或者 req.log.fatal({err}, 'msg');
+        ['warn', 'fatal', 'error'].forEach((level: string) => {
+            const ori = (req.log as any)[level];
+            (req.log as any)[level] = (...args: any[]) => {
+                const obj = args[0];
+                // 从对象提取出非 req、res、err、app字段，放置extraInfo，会自动加入日志
+                if (obj && obj.constructor === Object) {
+                    const extraInfo: any = {};
+                    const resOb: any = {};
+                    for (const key of Object.keys(obj)) {
+                        if (['req', 'res', 'err', 'app'].includes(key)) {
+                            resOb[key] = obj[key];
+                        }
+                        else {
+                            extraInfo[key] = obj[key];
+                        }
+                    }
+                    // 默认增加req
+                    resOb.req = resOb.req || req;
+                    args[0] = resOb;
+                }
+                // 默认增加req
+                else if (obj instanceof Error) {
+                    args[0] = {
+                        err: obj,
+                        req,
+                    };
+                }
+                // 默认增加req
+                else if (typeof obj === 'string') {
+                    args[0] = {
+                        msg: obj,
+                        req,
+                    };
+                }
+                ori.apply(req.log, args);
+            };
+        });
     };
 }
diff --git a/packages/app-autoload/src/hook/preParsing.ts b/packages/app-autoload/src/hook/preParsing.ts
@@ -0,0 +1,8 @@
+import {FastifyRequest} from 'fastify';
+import {performance} from 'perf_hooks';
+
+export const parseStartTimeSym = Symbol.for('hoth.parse-start-time');
+
+export default async function (req: FastifyRequest) {
+    req[parseStartTimeSym] = performance.now();
+}
diff --git a/packages/app-autoload/src/hook/preSerialization.ts b/packages/app-autoload/src/hook/preSerialization.ts
@@ -0,0 +1,8 @@
+import {FastifyRequest} from 'fastify';
+import {performance} from 'perf_hooks';
+
+export const serializationTimeSym = Symbol.for('hoth.serialization-time');
+
+export default async function (req: FastifyRequest) {
+    req[serializationTimeSym] = performance.now();
+}
diff --git a/packages/app-autoload/src/index.ts b/packages/app-autoload/src/index.ts
@@ -17,7 +17,10 @@ import {exit, loadModule} from '@hoth/utils';
 import onErrorFactory from './hook/onErrorFactory';
 import onSend from './hook/onSend';
 import preHandlerFactory from './hook/preHandlerFactory';
+import preSerialization from './hook/preSerialization';
 import onRequestFactory from './hook/onRequestFactory';
+import onResponse from './hook/onResponse';
+import preParsing from './hook/preParsing';
 import preValidation from './hook/preValidation';
 import {preHandler as loggerMiddleware} from '@hoth/logger';
 import {molecule} from '@hoth/molecule';
@@ -91,11 +94,15 @@ async function load(appConfig: AppConfig, childInstance: FastifyInstance) {
     childInstance.decorate('$appConfig', configProxy);
     childInstance.decorate('molecule', molecule);
 
-    childInstance.addHook('preValidation', preValidation);
+
     childInstance.addHook('onRequest', onRequestFactory(configProxy, childInstance));
+    childInstance.addHook('preParsing', preParsing);
+    childInstance.addHook('preValidation', preValidation);
     childInstance.addHook('preHandler', loggerMiddleware);
     childInstance.addHook('preHandler', preHandlerFactory(appConfig.name));
+    childInstance.addHook('preSerialization', preSerialization);
     childInstance.addHook('onSend', onSend);
+    childInstance.addHook('onResponse', onResponse);
 
     // load module plugins
     if (appConfig.pluginConfig) {

diff --git a/packages/cli/hoth-template/templates/normal/package.json b/packages/cli/hoth-template/templates/normal/package.json
@@ -55,7 +55,7 @@
   },
   "dependencies": {
     "@hoth/cli": "^__cliVersion__",
-    "fastify": "^3.19.1",
+    "fastify": "^3.29.4",
     "fastify-plugin": "^3.0.0",
     "nunjucks": "^3.2.3",
     "point-of-view": "^4.14.0"

diff --git a/packages/cli/hoth-template/templates/san-ssr-app/package.json b/packages/cli/hoth-template/templates/san-ssr-app/package.json
@@ -74,7 +74,7 @@
   "dependencies": {
     "@hoth/cli": "^__cliVersion__",
     "@hoth/view": "^1.2.1",
-    "fastify": "^3.19.1",
+    "fastify": "^3.29.4",
     "fastify-static": "^4.2.4",
     "san": "^3.11.2",
     "san-ssr": "^4.9.2",

diff --git a/packages/cli/hoth-template/templates/vue-ssr-app/package.json b/packages/cli/hoth-template/templates/vue-ssr-app/package.json
@@ -75,7 +75,7 @@
     "@hoth/cli": "^__cliVersion__",
     "@hoth/view": "^1.2.1",
     "@vue/server-renderer": "^3.2.31",
-    "fastify": "^3.27.4",
+    "fastify": "^3.29.4",
     "fastify-static": "^4.2.4",
     "swig": "^1.4.2",
     "tslib": "^2.3.1",

diff --git a/packages/decorators/src/index.ts b/packages/decorators/src/index.ts
@@ -58,7 +58,8 @@ declare module 'fastify' {
     }
 
     interface FastifyLoggerInstance {
-        addNotice: (key: string, value: string) => void;
+        addField: (key: string, value: string | number) => void;
+        addNotice: (key: string, value: string | number) => void;
         addPerformance: (name: string, value: number) => void;
     }
 

diff --git a/packages/logger/__tests__/logger.spec.ts b/packages/logger/__tests__/logger.spec.ts
@@ -158,19 +158,13 @@ describe('@hoth/logger logger', function () {
         const fun2 = compile(':foo[aa]');
         expect(fun2.toString()).toContain(':foo(aa)');
 
-        const fun3 = compile(':foo');
-        expect(fun3.toString()).toContain(':foo');
-    });
-
-    it('compile format', () => {
-        const fun1 = compile(':response-time[aa]');
-        expect(fun1.toString()).toContain('tokens[\"response-time\"](o, \"aa\") || \"-\")');
-
-        const fun2 = compile(':foo[aa]');
-        expect(fun2.toString()).toContain(':foo(aa)');
+        const fun3 = compile(':ua');
+        expect(fun3.toString()).toContain('tokens[\"ua\"]');
+        expect(fun3.toString()).toContain('-');
 
-        const fun3 = compile(':foo');
-        expect(fun3.toString()).toContain(':foo');
+        const fun4 = compile('+:fields');
+        expect(fun4.toString()).toContain('tokens[\"fields\"]');
+        expect(fun4.toString()).not.toContain('-');
     });
 
     it('stream flushSync', () => {

diff --git a/packages/logger/src/compile.ts b/packages/logger/src/compile.ts
@@ -4,9 +4,13 @@ export function compile(format: string) {
     return Function('tokens, o', 'return "' + format
         .replace(/"/g, '\\"')
         .replace(/\[\]/g, '')
-        .replace(/:([-\w]{2,})(?:\[([^\]]+)\])?/g, function (_, name, arg) {
+
+        // support +:field ,default value is ''
+        // support :field ,default value is '-'
+        .replace(/\+?:([-\w]{2,})(?:\[([^\]]+)\])?/g, function (match, name, arg) {
             return typeof tokens[name] === 'function'
-                ? `" + (tokens["${name}"](o` + (arg ? `, "${arg}"` : '') + ') || "-") + "'
+                ? `" + (tokens["${name}"](o` + (arg ? `, "${arg}"` : '') + ') || "'
+                    + (match.startsWith('+') ? '' : '-') + '") + "'
                 : (arg ? `:${name}(${arg})` : `:${name}`);
         }) + '\\n"');
 }