requestLogger.ts

/*!
 * Copyright (c) 2020 Ville de Montreal. All rights reserved.
 * Licensed under the MIT license.
 * See LICENSE file in the project root for full license information.
 */
import * as superagent from 'superagent';
import {
  Stopwatch,
  ILogger,
  extractMessageFromError,
} from '@villedemontreal/auth-core';

/**
 * plugin that will log a message before and after the execution of request,
 * and provide additional information such as status code, elapsed time, error...
 * @param logger the logger
 * @example
 * const req = superagent
 *   .get('http://localhost:4004/secured/profile')
 *   .use(requestLogger(new ConsoleLogger()));
 * @example
 * const correlator =  new HttpRequestCorrelator();
 * const req = superagent
 *   .get('http://localhost:4004/secured/profile')
 *   .use(requestLogger(new ConsoleLogger(() => correlator.getId())))
 *   .use(requestCorrelator(correlator));
 * @example
 * const agent = superagent
 *   .agent()
 *   .use(requestLogger(new ConsoleLogger()));
 * const req = agent.get('http://localhost:4004/secured/profile');
 * @example
 * const req = superagent
 *   .get('http://localhost:4004/secured/profile')
 *   .use(requestLogger(session.logger))
 *   .use(authenticator(session, authenticatorConfig));
 */
export function requestLogger(logger: ILogger) {
  return (request: superagent.SuperAgentRequest): superagent.Request => {
    const watch = Stopwatch.startNew();
    let responseLogged = false;
    // Note that we don't listen to the native http events
    // because we loose the correlation context that is maintained
    // only with the Superagent request EventEmitter.
    request.on('request', ({ req }) => {
      // we restart the watch just in case the request would be retried.
      watch.restart();
      const { url, method } = request;
      logger.debug({ method, url }, `Start of ${method} ${url}`);
    });
    request.on('response', (res: any) => {
      const { url, method } = request;
      const elapsedTimeInMS = watch.elapsedTimeInMS();
      const { statusCode } = res;
      logger.debug(
        { method, url, elapsedTimeInMS, statusCode },
        `End of ${method} ${url} => ${statusCode} in ${elapsedTimeInMS} ms`,
      );
      responseLogged = true;
    });

    request.on('error', (error: any) => {
      if (!responseLogged) {
        const { url, method } = request;
        const elapsedTimeInMS = watch.elapsedTimeInMS();
        const errorMessage = extractMessageFromError(error);
        // note that we clone and trim the error object to avoid
        // displaying too much information in the logs.
        const clonedError = { ...error, message: error.message };
        delete clonedError.response;
        logger.error(
          { method, url, elapsedTimeInMS, error: clonedError },
          `${method} ${url} failed in ${elapsedTimeInMS} ms: ${errorMessage}`,
        );
      }
    });

    return request;
  };
}