feat(logger): add parseTime & validationTime & pid

packages/app-autoload/src/hook/onRequestFactory.ts

@@ -1,8 +1,12 @@
+import {performance} from 'perf_hooks';
+
+export const parseStartTimeSym = Symbol.for('hoth.parse-start-time');
 
 export default function (appConfig, fastify) {
     return function (req, reply, done) {
         req.$appConfig = appConfig;
         req.$service = fastify;
+        req[parseStartTimeSym] = performance.now();
         done();
     };
 }

packages/app-autoload/src/hook/preHandlerFactory.ts

@@ -1,5 +1,15 @@
 import {FastifyReply, FastifyRequest} from 'fastify';
 import uuid from 'uuid-random';
+import {performance} from 'perf_hooks';
+import {parseStartTimeSym} from './onRequestFactory';
+import {validateStartTimeSym} from './preValidation';
+
+declare module 'fastify' {
+    interface FastifyRequest {
+        [validateStartTimeSym]: number;
+        [parseStartTimeSym]: number
+    }
+}
 
 export default function (app: string) {
     return function (req: FastifyRequest, reply: FastifyReply, done) {
@@ -8,6 +18,8 @@ export default function (app: string) {
             || (req.headers.logid as string)
             || uuid();
         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));
         done();
     };
 }

packages/app-autoload/src/hook/preValidation.ts

@@ -0,0 +1,8 @@
+import {FastifyReply, FastifyRequest} from 'fastify';
+import {performance} from 'perf_hooks';
+
+export const validateStartTimeSym = Symbol.for('hoth.validate-start-time');
+
+export default async function (req: FastifyRequest, reply: FastifyReply) {
+    req[validateStartTimeSym] = performance.now();
+}

packages/app-autoload/src/index.ts

@@ -18,6 +18,7 @@ import onErrorFactory from './hook/onErrorFactory';
 import onSend from './hook/onSend';
 import preHandlerFactory from './hook/preHandlerFactory';
 import onRequestFactory from './hook/onRequestFactory';
+import preValidation from './hook/preValidation';
 import {preHandler as loggerMiddleware} from '@hoth/logger';
 import {molecule} from '@hoth/molecule';
 import {loadConfig} from './configLoader';
@@ -133,9 +134,10 @@ async function load(appConfig: AppConfig, childInstance: FastifyInstance) {
     // load molecule
     await loadMoleculeApp(appConfig, childInstance);
 
+    childInstance.addHook('preValidation', preValidation);
     childInstance.addHook('onRequest', onRequestFactory(configProxy, childInstance));
-    childInstance.addHook('preHandler', preHandlerFactory(appConfig.name));
     childInstance.addHook('preHandler', loggerMiddleware);
+    childInstance.addHook('preHandler', preHandlerFactory(appConfig.name));
     childInstance.addHook('onSend', onSend);
 
     return childInstance;

packages/logger/src/constants.ts

@@ -11,17 +11,17 @@ export const defaultLevels = {
 };
 
 const normalFormat = ':level: :time [:file::line]'
-    + ' errno[:errno] logId[:logid]'
+    + ' errno[:errno] logId[:logid] pid[:pid]'
     + ' uri[:uri] app[:app] product[:product] module[:module]'
     + ' clientIp[:ip] ua[:ua] refer[:referrer] cookie[:cookie] :msg';
 
 const noticeFormat = ':level: :time [:file::line]'
-    + ' errno[:errno] status[:status] logId[:logid]'
+    + ' errno[:errno] status[:status] logId[:logid] pid[:pid]'
     + ' uri[:uri] app[:app] product[:product] module[:module]'
     + ' clientIp[:ip] ua[:ua] refer[:referrer] cookie[:cookie] :notices tm[:performance] responseTime[:response-time]';
 
 const errorFormat = ':level: :time [:file::line]'
-    + ' errno[:errno] status[:status] logId[:logid]'
+    + ' errno[:errno] status[:status] logId[:logid] pid[:pid]'
     + ' uri[:uri] app[:app] product[:product] module[:module]'
     + ' clientIp[:ip] ua[:ua] refer[:referrer] cookie[:cookie] :errmsg';