Add info logging for metrics (#21)

* Add basic duration info logging to:
  - service
  - events
  - resource
* Change to `JSON.stringify` in error logging
* Bump prettier and tslint versions

dist/src/request.d.ts

@@ -21,3 +21,15 @@ export interface ReplyOptions {
     contentType?: string;
     headers?: Headers;
 }
+export declare const createDurationLogInfo: (request: Request, message: string, startTimestamp: number, endTimestamp: number) => {
+    message: string;
+    properties: {
+        type?: string | undefined;
+        replyTo?: string | undefined;
+        headers: {
+            [key: string]: unknown;
+        };
+    };
+    queue: string | undefined;
+    duration: number;
+};

package.json

@@ -1,6 +1,6 @@
 {
   "name": "mq",
-  "version": "4.0.0",
+  "version": "4.1.0",
   "description": "A declarative abstraction layer for writing event handlers.",
   "main": "./dist/src/mq.js",
   "types": "./dist/src/mq.d.ts",
@@ -49,11 +49,11 @@
     "istanbul": "^0.4.5",
     "mocha": "^6.2.0",
     "nyc": "^14.1.1",
-    "prettier": "^1.18.2",
+    "prettier": "^1.19.1",
     "sinon": "^7.3.2",
     "source-map-support": "^0.5.12",
     "ts-node": "^8.3.0",
-    "tslint": "^5.18.0",
+    "tslint": "^6.0.0",
     "tslint-insurello": "github:insurello/tslint-insurello#v2.0.6",
     "typescript": "^3.5.3",
     "winston": "^3.1.0"

src/errors.ts

@@ -29,10 +29,10 @@ export const errorHandler = (req: Request, logger: Logger) => (
     logger.error(err.stack ? err.stack : err.message, requestInfo);
   } else if (isError(err)) {
     response(req)(err, { "x-error": err.error });
-    logger.warn(`${err}`, requestInfo);
+    logger.warn(JSON.stringify(err), requestInfo);
   } else if (typeof err === "string") {
     response(req)({ error: err }, { "x-error": err });
-    logger.warn(`${err}`, requestInfo);
+    logger.warn(JSON.stringify(err), requestInfo);
   } else {
     req.reject();
     logger.verbose("rejected", requestInfo);

src/events.ts

@@ -2,7 +2,7 @@ import * as t from "io-ts";
 import { decode } from "./decoder";
 import { errorHandler } from "./errors";
 import { Logger, logger } from "./logger";
-import { Request } from "./request";
+import { createDurationLogInfo, Request } from "./request";
 
 const defaultEventField = "event";
 
@@ -32,6 +32,7 @@ interface EventCallbackStyle<T, C, O> {
 export const events = <T, C = any, O = T>(desc: Events<T, C, O>) => {
   const _logger = desc.logger ? desc.logger : logger;
   return (options: any) => (req: Request) => {
+    const durationStart = Date.now();
     return Promise.resolve(desc.init(options))
       .then(context =>
         decode(desc.type, req.body).then(data =>
@@ -41,7 +42,17 @@ export const events = <T, C = any, O = T>(desc: Events<T, C, O>) => {
         )
       )
       .then(() => req.ack())
-      .then(a => a, errorHandler(req, _logger));
+      .then(success => {
+        _logger.info(
+          createDurationLogInfo(
+            req,
+            "Event processed",
+            durationStart,
+            Date.now()
+          )
+        );
+        return success;
+      }, errorHandler(req, _logger));
   };
 };