From 49958cb2741ee63c796103edc583915799310f47 Mon Sep 17 00:00:00 2001
From: yangqiqi <imshuazi@126.com>
Date: Thu, 8 Apr 2021 16:53:05 +0800
Subject: [PATCH] log every request info

---
 package.json                   |  4 ++-
 src/app.js                     |  4 ++-
 src/middlewares/http-logger.js | 47 ++++++++++++++++++++++++++++++++++
 yarn.lock                      |  4 +--
 4 files changed, 55 insertions(+), 4 deletions(-)
 create mode 100644 src/middlewares/http-logger.js

diff --git a/package.json b/package.json
index b090ef31..6de9f286 100644
--- a/package.json
+++ b/package.json
@@ -72,7 +72,9 @@
     "swagger-ui-express": "^4.1.6",
     "validator": "^13.0.0",
     "winston": "^3.2.1",
-    "xss-clean": "^0.1.1"
+    "xss-clean": "^0.1.1",
+    "on-finished": "^2.3.0",
+    "on-headers": "^1.0.2"
   },
   "devDependencies": {
     "coveralls": "^3.0.7",
diff --git a/src/app.js b/src/app.js
index 4af80b4d..e44aef82 100644
--- a/src/app.js
+++ b/src/app.js
@@ -12,6 +12,7 @@ const { jwtStrategy } = require('./config/passport');
 const { authLimiter } = require('./middlewares/rateLimiter');
 const routes = require('./routes/v1');
 const { errorConverter, errorHandler } = require('./middlewares/error');
+const { httplogger } = require('./middlewares/http-logger');
 const ApiError = require('./utils/ApiError');
 
 const app = express();
@@ -20,7 +21,8 @@ if (config.env !== 'test') {
   app.use(morgan.successHandler);
   app.use(morgan.errorHandler);
 }
-
+// log per req info
+app.use(httplogger);
 // set security HTTP headers
 app.use(helmet());
 
diff --git a/src/middlewares/http-logger.js b/src/middlewares/http-logger.js
new file mode 100644
index 00000000..3b14f9c2
--- /dev/null
+++ b/src/middlewares/http-logger.js
@@ -0,0 +1,47 @@
+const onFinished = require('on-finished');
+const onHeaders = require('on-headers');
+const logger = require('../config/logger');
+
+function startTime() {
+  this._startAt = process.hrtime();
+}
+
+const calResponseTime = (req, res) => {
+  if (!req._startAt || !res._startAt) {
+    return;
+  }
+  const ms = (res._startAt[0] - req._startAt[0]) * 1e3 + (res._startAt[1] - req._startAt[1]) * 1e-6;
+  return ms;
+};
+
+// log time&req info
+const httplogger = (req, res, next) => {
+  req._startAt = undefined;
+  res._startAt = undefined;
+  startTime.call(req);
+
+  onHeaders(res, startTime);
+  onFinished(res, (err, resp) => {
+    const statusCode = resp._header ? resp.statusCode : undefined;
+
+    if (err) {
+      logger.error(`[error] url: ${req.url} :${err}`);
+    }
+
+    const msg =
+      `[url]: ${req.url}` +
+      '---' +
+      `[restime]: ${calResponseTime(req, res)}ms --- ` +
+      `[statusCode]: ${statusCode}` +
+      ` [method]: ${req.method}` +
+      `[body]: ${JSON.stringify(req.body)}` +
+      ` &[query]: ${JSON.stringify(req.query)}` +
+      ` &[headers]: ${JSON.stringify(req.headers)}`;
+    logger.info(msg);
+  });
+  next();
+};
+
+module.exports = {
+  httplogger,
+};
diff --git a/yarn.lock b/yarn.lock
index 9035d64f..5e61386e 100644
--- a/yarn.lock
+++ b/yarn.lock
@@ -4973,14 +4973,14 @@ object.values@^1.1.1:
     es-abstract "^1.18.0-next.2"
     has "^1.0.3"
 
-on-finished@~2.3.0:
+on-finished@^2.3.0, on-finished@~2.3.0:
   version "2.3.0"
   resolved "https://registry.yarnpkg.com/on-finished/-/on-finished-2.3.0.tgz#20f1336481b083cd75337992a16971aa2d906947"
   integrity sha1-IPEzZIGwg811M3mSoWlxqi2QaUc=
   dependencies:
     ee-first "1.1.1"
 
-on-headers@~1.0.2:
+on-headers@^1.0.2, on-headers@~1.0.2:
   version "1.0.2"
   resolved "https://registry.yarnpkg.com/on-headers/-/on-headers-1.0.2.tgz#772b0ae6aaa525c399e489adfad90c403eb3c28f"
   integrity sha512-pZAE+FJLoyITytdqK0U5s+FIpjN0JP3OzFi/u8Rx+EV5/W+JTWGXG8xFzevE7AjBfDqHv/8vL8qQsIhHnqRkrA==