feat(logging): add log option (#457)

jest.config.ts

@@ -18,6 +18,7 @@ const config: Config.InitialOptions = {
     },
   },
   preset: "ts-jest",
+  restoreMocks: true,
   testEnvironment: "node",
   testRegex: /test\/.*\/.*.test.ts/u.source,
 };

src/event-handler/index.ts

@@ -2,6 +2,7 @@ import type {
   EmitterWebhookEvent,
   EmitterWebhookEventName,
   HandlerFunction,
+  Logger,
   Options,
   State,
   WebhookEventHandlerError,
@@ -33,6 +34,7 @@ export function createEventHandler<TTransformed>(
 ): EventHandler<TTransformed> {
   const state: State = {
     hooks: {},
+    log: createLogger(options.log),
   };
 
   if (options && options.transform) {
@@ -47,3 +49,13 @@ export function createEventHandler<TTransformed>(
     receive: receive.bind(null, state),
   };
 }
+
+export function createLogger(logger?: Partial<Logger>) {
+  return {
+    debug: () => {},
+    info: /* istanbul ignore next: unused */ () => {},
+    warn: console.warn.bind(console),
+    error: console.error.bind(console),
+    ...logger,
+  };
+}

src/event-handler/on.ts

@@ -41,7 +41,7 @@ export function receiverOn(
   }
 
   if (emitterEventNames.indexOf(webhookNameOrNames) === -1) {
-    console.warn(
+    state.log.warn(
       `"${webhookNameOrNames}" is not a known webhook name (https://developer.github.com/v3/activity/events/types/)`
     );
   }

src/index.ts

@@ -1,5 +1,5 @@
 import { IncomingMessage, ServerResponse } from "http";
-import { createEventHandler } from "./event-handler/index";
+import { createEventHandler, createLogger } from "./event-handler/index";
 import { createMiddleware } from "./middleware/index";
 import { middleware } from "./middleware/middleware";
 import { verifyAndReceive } from "./middleware/verify-and-receive";
@@ -52,6 +52,7 @@ class Webhooks<
       path: options.path || "/",
       secret: options.secret,
       hooks: {},
+      log: createLogger(options.log),
     };
 
     this.sign = sign.bind(null, options.secret);

src/middleware/index.ts

@@ -1,4 +1,5 @@
-import { createEventHandler } from "../event-handler/index";
+import { debug } from "debug";
+import { createEventHandler, createLogger } from "../event-handler/index";
 import { middleware } from "./middleware";
 import { Options, State } from "../types";
 
@@ -12,6 +13,7 @@ export function createMiddleware(options: Options<any>) {
     path: options.path || "/",
     secret: options.secret,
     hooks: {},
+    log: createLogger(options.log || { debug: debug("webhooks:receiver") }),
   };
 
   const api: any = middleware.bind(null, state);

src/middleware/middleware.ts

@@ -3,12 +3,9 @@ import { isntWebhook } from "./isnt-webhook";
 import { getMissingHeaders } from "./get-missing-headers";
 import { getPayload } from "./get-payload";
 import { verifyAndReceive } from "./verify-and-receive";
-import { debug } from "debug";
 import { IncomingMessage, ServerResponse } from "http";
 import { State, WebhookEventHandlerError } from "../types";
 
-const debugWebhooks = debug("webhooks:receiver");
-
 export function middleware(
   state: State,
   request: IncomingMessage,
@@ -25,7 +22,7 @@ export function middleware(
       return;
     }
 
-    debugWebhooks(`ignored: ${request.method} ${request.url}`);
+    state.log.debug(`ignored: ${request.method} ${request.url}`);
     response.statusCode = 404;
     response.end("Not found");
     return;
@@ -48,7 +45,7 @@ export function middleware(
   const signatureSHA256 = request.headers["x-hub-signature-256"] as string;
   const id = request.headers["x-github-delivery"] as string;
 
-  debugWebhooks(`${eventName} event received (id: ${id})`);
+  state.log.debug(`${eventName} event received (id: ${id})`);
 
   // GitHub will abort the request if it does not receive a response within 10s
   // See https://github.com/octokit/webhooks.js/issues/185

src/types.ts

@@ -27,6 +27,7 @@ export interface Options<
   path?: string;
   secret?: string;
   transform?: TransformMethod<T, TTransformed>;
+  log?: Partial<Logger>;
 }
 
 type TransformMethod<T extends EmitterWebhookEvent, V = T> = (
@@ -42,9 +43,17 @@ type Hooks = {
   [key: string]: Function[];
 };
 
+export interface Logger {
+  debug: (message: string) => unknown;
+  info: (message: string) => unknown;
+  warn: (message: string) => unknown;
+  error: (message: string) => unknown;
+}
+
 export interface State extends Options<any> {
   eventHandler?: any;
   hooks: Hooks;
+  log: Logger;
 }
 
 /**

test/integration/middleware-test.ts

@@ -33,7 +33,7 @@ test("Invalid payload", () => {
     statusCode: 0,
   };
 
-  const middleware = createMiddleware({ secret: "mysecret" });
+  const middleware = createMiddleware({ secret: "mysecret", log: {} });
   const middlewareDone = middleware(requestMock, responseMock).then(() => {
     expect(responseMock.statusCode).toBe(400);
     expect(responseMock.end).toHaveBeenCalledWith(
@@ -61,7 +61,7 @@ test("request error", () => {
     statusCode: 0,
   };
 
-  const middleware = createMiddleware({ secret: "mysecret" });
+  const middleware = createMiddleware({ secret: "mysecret", log: {} });
   const middlewareDone = middleware(requestMock, responseMock).then(() => {
     expect(responseMock.statusCode).toBe(500);
     expect(responseMock.end).toHaveBeenCalledWith(

test/unit/event-handler-on-test.ts

@@ -5,6 +5,7 @@ function noop() {}
 
 const state: State = {
   hooks: {},
+  log: console,
 };
 
 beforeEach(() => jest.resetAllMocks());

test/unit/event-handler-receive-test.ts

@@ -4,6 +4,7 @@ import { State } from "../../src/types";
 const state: State = {
   secret: "mysecret",
   hooks: {},
+  log: console,
 };
 
 test("options: none", () => {

test/unit/event-handler-remove-listener-test.ts

@@ -8,10 +8,11 @@ test("remove-listener: single listener", () => {
     hooks: {
       push: [push],
     },
+    log: console,
   };
 
   expect(() => removeListener(state, "push", push)).not.toThrow();
-  expect(state).toStrictEqual({ hooks: { push: [] } });
+  expect(state).toStrictEqual({ hooks: { push: [] }, log: console });
 });
 
 test("remove-listener: multiple listeners", () => {
@@ -26,12 +27,16 @@ test("remove-listener: multiple listeners", () => {
       push: [push1, push2, push3],
       ping: [ping],
     },
+    log: console,
   };
 
   expect(() => {
     removeListener(state, "push", push1);
     removeListener(state, "push", push2);
     removeListener(state, "push", push3);
   }).not.toThrow();
-  expect(state).toStrictEqual({ hooks: { push: [], ping: [ping] } });
+  expect(state).toStrictEqual({
+    hooks: { push: [], ping: [ping] },
+    log: console,
+  });
 });

test/unit/middleware-test.ts

@@ -1,23 +1,27 @@
 import { IncomingMessage, ServerResponse } from "http";
 import { middleware } from "../../src/middleware/middleware";
-import { getMissingHeaders } from "../../src/middleware/get-missing-headers";
 import { getPayload } from "../../src/middleware/get-payload";
 import { verifyAndReceive } from "../../src/middleware/verify-and-receive";
 
-jest.mock("../../src/middleware/get-missing-headers");
 jest.mock("../../src/middleware/get-payload");
 jest.mock("../../src/middleware/verify-and-receive");
 
-const mockGetMissingHeaders = getMissingHeaders as jest.Mock;
 const mockGetPayload = getPayload as jest.Mock;
 const mockVerifyAndReceive = verifyAndReceive as jest.Mock;
 
+const headers = {
+  "x-github-delivery": "123e4567-e89b-12d3-a456-426655440000",
+  "x-github-event": "push",
+  "x-hub-signature": "sha1=f4d795e69b5d03c139cc6ea991ad3e5762d13e2f",
+};
+
 test("next() callback", () => {
   const next = jest.fn();
 
   middleware(
     {
       hooks: {},
+      log: console,
     },
     { method: "POST", url: "/foo" } as IncomingMessage,
     {} as ServerResponse,
@@ -33,20 +37,20 @@ describe("when does a timeout on retrieving the payload", () => {
   });
 
   test("successfully, does NOT response.end(ok)", async () => {
+    const consoleDebugSpy = jest.spyOn(console, "debug").mockImplementation();
     const responseMock = ({ end: jest.fn() } as unknown) as ServerResponse;
     const next = jest.fn();
 
-    mockGetMissingHeaders.mockReturnValueOnce([]);
     mockGetPayload.mockResolvedValueOnce(undefined);
     mockVerifyAndReceive.mockResolvedValueOnce(undefined);
 
     const promiseMiddleware = middleware(
-      { hooks: {}, path: "/foo" },
-      {
+      { hooks: {}, path: "/foo", log: console },
+      ({
         method: "POST",
         url: "/foo",
-        headers: {},
-      } as IncomingMessage,
+        headers,
+      } as unknown) as IncomingMessage,
       responseMock,
       next
     );
@@ -56,26 +60,30 @@ describe("when does a timeout on retrieving the payload", () => {
     await promiseMiddleware;
 
     expect(next).not.toHaveBeenCalled();
+    expect(consoleDebugSpy).toHaveBeenCalledTimes(1);
+    expect(consoleDebugSpy).toHaveBeenLastCalledWith(
+      "push event received (id: 123e4567-e89b-12d3-a456-426655440000)"
+    );
     expect(setTimeout).toHaveBeenCalledTimes(1);
     expect(responseMock.end).toHaveBeenCalledWith("still processing\n");
     expect(responseMock.end).not.toHaveBeenCalledWith("ok\n");
   });
 
   test("failing, does NOT response.end(ok)", async () => {
+    const consoleDebugSpy = jest.spyOn(console, "debug").mockImplementation();
     const responseMock = ({ end: jest.fn() } as unknown) as ServerResponse;
     const next = jest.fn();
 
-    mockGetMissingHeaders.mockReturnValueOnce([]);
     mockGetPayload.mockResolvedValueOnce(undefined);
     mockVerifyAndReceive.mockRejectedValueOnce(new Error("random error"));
 
     const promiseMiddleware = middleware(
-      { hooks: {}, path: "/foo" },
-      {
+      { hooks: {}, path: "/foo", log: console },
+      ({
         method: "POST",
         url: "/foo",
-        headers: {},
-      } as IncomingMessage,
+        headers,
+      } as unknown) as IncomingMessage,
       responseMock,
       next
     );
@@ -85,6 +93,10 @@ describe("when does a timeout on retrieving the payload", () => {
     await promiseMiddleware;
 
     expect(next).not.toHaveBeenCalled();
+    expect(consoleDebugSpy).toHaveBeenCalledTimes(1);
+    expect(consoleDebugSpy).toHaveBeenLastCalledWith(
+      "push event received (id: 123e4567-e89b-12d3-a456-426655440000)"
+    );
     expect(setTimeout).toHaveBeenCalledTimes(1);
     expect(responseMock.end).toHaveBeenCalledWith("still processing\n");
     expect(responseMock.end).not.toHaveBeenCalledWith(