Logging from Middleware

[ajoslin103]

I've a middleware that connects to a rabbit server via .env file settings -- when the connection is refused by the remote server the connection errored functions' log statements are never seen anywhere

How can I log something from Middleware?

'use strict'
/** @typedef {import('@adonisjs/framework/src/Request')} Request */
/** @typedef {import('@adonisjs/framework/src/Response')} Response */
/** @typedef {import('@adonisjs/framework/src/View')} View */

/** @type {import('@adonisjs/framework/src/Env')} */
const Env = use('Env');

/** @type {import('@adonisjs/framework/src/Logger')} */
const Logger = use('Logger'); // set logLevel in environment, consumed in .../start/routes.js

const LOGSRC = 'RabbitMiddleware';

const Rabbit = use('Rabbit/Provider');

class RabbitMiddleware {

  // open the channel, setup error handlers, call next(), shutdown channel
  async handle({ request }, next, routing) {
    try {
      const [usage] = [...routing];
      Logger.debug(`${LOGSRC} building rabbitParms for: ${usage}`);
      // determine the rabbit
      const rabbitParms = Rabbit.chooseWarren(usage)
      const { rabbitHost, rabbitPort } = { ...rabbitParms };
      if (rabbitHost !== `:${rabbitPort}`) {
        Logger.debug(`${LOGSRC} rabbitParms: ${JSON.stringify(rabbitParms)}`);
        // legitimize the rabbit - store in the request for later users
        request.rabbit = await Rabbit.openWarren(rabbitParms)
        const { connection, channel } = { ...request.rabbit };
        if (connection) {
          Logger.debug(`${LOGSRC} connection open`);
          connection.on('error', err => {
            throw new Error(`connection errored: ${err.message}`);
          });
          if (channel) {
            Logger.debug(`${LOGSRC} channel open`);
            channel.on('error', err => {
              throw new Error(`channel errored: ${err.message}`);
            });
            // Execute next middleware / route handler
            try {
              await next()
            } catch (err) {
              Logger.error(`${LOGSRC}.next  RouteHandler threw: ${err.message}`);
            }
            // release the rabbit
            await Rabbit.closeWarren(request.rabbit)
          }
        }
      }
    } catch (err) {
      const rabbitConnectionUrl = await Rabbit.closeWarren(request.rabbit)
      Logger.error(`${LOGSRC} threw: ${err.message}, rabbitUrl: ${rabbitConnectionUrl}, connection closed`);
    }
  }
}

module.exports = RabbitMiddleware

'use strict'

/** @type {import('@adonisjs/framework/src/Env')} */
const Env = use('Env')

/** @type {import('@adonisjs/framework/src/Logger')} */
const Logger = use('Logger'); // set logLevel in environ

const LOGSRC = 'RabbitProvider';

const DIRECT = 'direct';
const FIELDS = '_FIELDS';
const NOOP = () => { };

class Rabbit {

  // ------------- working functions -------------

  // split a 'fieldsTag' ENV var for object creation
  assembleOptions(fieldsTag = '') {
    try {
      return Env.get(`${fieldsTag}`, '')
        .split(',')
        .reduce((running, tag) => {
          const suffix = tag.toUpperCase();
          const value = Env.get(fieldsTag.replace(FIELDS, suffix), '');
          if (value) { running[tag] = value; }
          return running;
        }, {});
    } catch (err) {
      Logger.error(`${LOGSRC}.assembleOptions threw: ${err.message}`);
    }
  }

  // http://www.squaremobius.net/amqp.node/channel_api.html#channel_assertExchange
  async assertDirectExchange(channel, exchange, exchangeOpts = {}) {
    return await channel.assertExchange(exchange, DIRECT, exchangeOpts);
  }

  // http://www.squaremobius.net/amqp.node/channel_api.html#channel_assertQueue
  async assertQueue(channel, queue, queueOpts = {}) {
    return await channel.assertQueue(queue, queueOpts);
  }

  // http://www.squaremobius.net/amqp.node/channel_api.html#channel_publish
  async publishToExchange({ rabbit, contentStr, exchange, exchangeOpts = {}, publishOpts = {}, routingKey = '' }) {
    try {
      const { channel } = { ...rabbit };
      const assertResult = await this.assertDirectExchange(channel, exchange, exchangeOpts);
      return await channel.publish(assertResult.assertExchange, routingKey, Buffer.from(contentStr), publishOpts);
    } catch (err) {
      Logger.error(`${LOGSRC}.publishToExchange threw: ${err.message}`);
    }
  }

  // http://www.squaremobius.net/amqp.node/channel_api.html#channel_consume
  async subscribeWithoutAck({ rabbit, queue, consumeFn = NOOP, queueOpts = {} }) {
    try {
      const { channel } = { ...rabbit };
      const assertResult = await this.assertQueue(channel, queue, queueOpts);
      channel.consume(assertResult.queue, (msg) => {
        consumeFn(msg);
      }, { noAck: true });
    } catch (err) {
      Logger.error(`${LOGSRC}.subscribeWithoutAck threw: ${err.message}`);
    }
  }

  // ------------- warren connectivity -------------

  // assemble connection information
  chooseWarren(usage = '') {
    try {
      const Usage = usage.toUpperCase();
      const params = {
        usage: Usage,
        rabbitUser: Env.get(`${Usage}_RABBIT_USER`, ''),
        rabbitPass: Env.get(`${Usage}_RABBIT_PASS`, ''),
        rabbitHost: Env.get(`${Usage}_RABBIT_HOST`, ''),
        rabbitPort: Env.get(`${Usage}_RABBIT_PORT`, 5672),
      };
      params.rabbitPass = params.rabbitPass ? `:${params.rabbitPass}` : '';
      params.rabbitAuth = params.rabbitUser ? `${params.rabbitUser}${params.rabbitPass}@` : '';
      params.rabbitHost = (/:/.test(params.rabbitHost) ? params.rabbitHost : `${params.rabbitHost}:${params.rabbitPort}`)
      params.rabbitConnectionUrl = `amqp://${params.rabbitAuth}${params.rabbitHost}`;
      return params;
    } catch (err) {
      Logger.error(`${LOGSRC}.chooseWarren threw: ${err.message}`);
    }
  }

  // open the connection and establish a channel
  // result is a rabbit [connection, channel, rabbitParms] from the warren
  async openWarren(rabbitParms, cleanupFn = errMsg => Logger.emerg(errMsg)) {
    const { rabbitConnectionUrl } = { ...rabbitParms };
    Logger.debug(`${LOGSRC}.openWarren rabbitConnectionUrl: ${rabbitConnectionUrl}`)
    try {
      // https://www.npmjs.com/package/amqplib
      const amqplib = require('amqplib');
      // http://www.squaremobius.net/amqp.node/channel_api.html
      const openAMQ = amqplib.connect(rabbitConnectionUrl);
      const connection = await openAMQ;
      const channel = await connection.createChannel();
      return { connection, channel, rabbitParms };
    } catch (err) {
      Logger.error(`${LOGSRC}.openWarren threw: ${err.message}`);
    }
    return { connection: false, channel: false, rabbitParms }
  }

  // definitively close the channel
  async closeWarren(rabbit) {
    try {
      if (rabbit) {
        Logger.debug(`${LOGSRC}.closeWarren rabbit.rabbitParms: ${JSON.stringify(rabbit.rabbitParms)}`)
        if (rabbit.channel) {
          await rabbit.channel.close();
          rabbit.channel = false;
        }
        const { rabbitConnectionUrl } = { ...rabbit.rabbitParms };
        return rabbitConnectionUrl;
      }
    } catch (err) {
      Logger.error(`${LOGSRC}.closeWarren threw: ${err.message}`);

    }
  }
}

module.exports = Rabbit

[ajoslin103]

in the console, running under: adonis serve --dev we get this:

notice: Logging level set from .env in .../start/routes.js
info: serving app on http://0.0.0.0:3333
debug: RabbitMiddleware building rabbitParms for: activation
debug: RabbitMiddleware rabbitParms: {"usage":"ACTIVATION","rabbitUser":"","rabbitPass":"","rabbitHost":"p4.epc-instore.com:5672","rabbitPort":"5672","rabbitAuth":"","rabbitConnectionUrl":"amqp://p4.epc-instore.com:5672"}
debug: RabbitProvider.openWarren rabbitConnectionUrl: amqp://p4.epc-instore.com:5672
debug: RabbitMiddleware connection open
debug: RabbitMiddleware channel open
error: RabbitMiddleware.next  RouteHandler threw: Unexpected token =
debug: RabbitProvider.closeWarren rabbit.rabbitParms: {"usage":"ACTIVATION","rabbitUser":"","rabbitPass":"","rabbitHost":"p4.epc-instore.com:5672","rabbitPort":"5672","rabbitAuth":"","rabbitConnectionUrl":"amqp://p4.epc-instore.com:5672"}

And in the debugger we see this:

Debugger attached.
notice: Logging level set from .env in .../start/routes.js
info: serving app on http://0.0.0.0:3333
debug: RabbitMiddleware building rabbitParms for: activation
debug: RabbitMiddleware rabbitParms: {"usage":"ACTIVATION","rabbitUser":"","rabbitPass":"","rabbitHost":"p4.epc-instore.com:5672","rabbitPort":"5672","rabbitAuth":"","rabbitConnectionUrl":"amqp://p4.epc-instore.com:5672"}
debug: RabbitProvider.openWarren rabbitConnectionUrl: amqp://p4.epc-instore.com:5672
debug: RabbitMiddleware connection open
debug: RabbitMiddleware channel open
Waiting for the debugger to disconnect...
/Users/ajoslin/Documents/Als/Development/EPC/Development/mobile-club/mobile-club-backend/app/Middleware/RabbitMiddleware.js:34
            throw new Error(`connection errored: ${err.message}`);
            ^

Error: connection errored: channel errored: Channel closed by server: 406 (PRECONDITION-FAILED) with message "PRECONDITION_FAILED - inequivalent arg 'durable' for exchange 'mobile_activation_exchange' in vhost '/': received 'true' but current is 'false'"
    at ChannelModel.<anonymous> (/Users/ajoslin/Documents/Als/Development/EPC/Development/mobile-club/mobile-club-backend/app/Middleware/RabbitMiddleware.js:34:19)
    at ChannelModel.emit (events.js:210:5)
    at Connection.emit (events.js:210:5)
    at Connection.C.onSocketError (/Users/ajoslin/Documents/Als/Development/EPC/Development/mobile-club/mobile-club-backend/node_modules/amqplib/lib/connection.js:353:10)
    at Connection.emit (events.js:210:5)
    at Socket.go (/Users/ajoslin/Documents/Als/Development/EPC/Development/mobile-club/mobile-club-backend/node_modules/amqplib/lib/connection.js:481:12)
    at Socket.emit (events.js:210:5)
    at emitReadable_ (_stream_readable.js:574:12)
    at processTicksAndRejections (internal/process/task_queues.js:79:21)
Application crashed, make sure to kill all related running process, fix the issue and re-run the app