Merge pull request bitpay#1807 from micahriggan/feature/request-logging

Better request logging

packages/bitcore-node/src/routes/middleware.ts

@@ -5,14 +5,40 @@ type TimedRequest = {
   startTime?: Date;
 } & express.Request;
 
+function LogObj(logOut: { [key: string]: string }) {
+  logger.info(
+    `${logOut.time} | ${logOut.ip} | ${logOut.phase} | ${logOut.took} | ${logOut.method} | ${logOut.status} | ${
+      logOut.url
+    }`
+  );
+}
+
 export function LogRequest(req: TimedRequest, res: express.Response, next: express.NextFunction) {
   req.startTime = new Date();
-  res.on('finish', () => {
+  const ip = req.header('CF-Connecting-IP') || req.socket.remoteAddress || req.hostname;
+  const logOut = {
+    time: req.startTime.toTimeString(),
+    ip: ip.padStart(12, ' '),
+    phase: 'START'.padStart(8, ' '),
+    method: req.method.padStart(6, ' '),
+    status: '...'.padStart(5, ' '),
+    url: `${req.baseUrl}${req.url}`,
+    took: '...'.padStart(10, ' ')
+  };
+  LogObj(logOut);
+
+  const LogPhase = (phase: string) => () => {
     const endTime = new Date();
     const startTime = req.startTime ? req.startTime : endTime;
     const totalTime = endTime.getTime() - startTime.getTime();
-    const totalTimeMsg = `${totalTime} ms`.padStart(10, ' ');;
-    logger.info(`${startTime.toTimeString()} | ${totalTimeMsg} | ${req.method} | ${req.baseUrl}${req.url}`);
-  });
+    const totalTimeMsg = `${totalTime} ms`;
+    logOut.phase = phase.padStart(8, ' ');
+    logOut.took = totalTimeMsg.padStart(10, ' ');
+    logOut.status = res.statusCode.toString().padStart(5, ' ');
+    LogObj(logOut);
+  };
+
+  res.on('finish', LogPhase('END'));
+  res.on('close', LogPhase('CLOSED'));
   next();
 }