Failed or Not complete logging with winston cloudwatch logging

[prinarjayaoka]

Hi Dev Team,

I log with https://github.com/lazywithclass/winston-cloudwatch . It runs well and perfect inside expressjs. Then come the time I need to create a job scheduler. I choose Breejs.

My logging sometimes failed, and sometimes success, but when success it only log some. For example
I have 3 loggin

log.info('Logging one'); 
log.info('Logging two'); 
log.info('Logging one')

ONLY Logging one logged into cloudwatch log

I share my complete code

const Graceful = require('@ladjs/graceful');
const Bree = require('bree');

const scheduler = new Bree({
  jobs: [
    {
      name: 'cancel-order.job',
      interval: process.env.CANCEL_ORDER_INTERVAL,
    },
    {
      name: 'retry-generate-awb.job',
      interval: process.env.RETRY_GENERATE_AWB_INTERVAL,
    },
  ],
});

const gracefully = new Graceful({ brees: [scheduler] });

gracefully.listen();

scheduler.start();

// retry-generate-awb.job.js

const os = require('os');
const pMap = require('p-map');
const { parentPort } = require('worker_threads');
const { importModels } = require('@myorg/utils/models');
const amqp = require('amqplib');
const {
  PROCESSING,
} = require('@myorg/utils/configs/order-status.config');
const { logger, esTransport } = require('../logger');

logger.on('error', error => {
  // eslint-disable-next-line no-console
  console.error('Error caught', error);
});
esTransport.on('warning', error => {
  // eslint-disable-next-line no-console
  console.error('Error caught', error);
});

const { sequelizeInstance, Sequelize } = require('../db');

const {
  RABBITMQ_HOST,
  RABBITMQ_USER,
  RABBITMQ_PASS,
  RABBITMQ_QUEUE_RETRY_GENERATE_AWB,
} = process.env;

let isCancelled = false;
const concurrency = os.cpus().length;
const models = importModels(sequelizeInstance, Sequelize);

const connectionOpts = {
  protocol: 'amqps',
  hostname: RABBITMQ_HOST,
  port: '5671',
  username: RABBITMQ_USER,
  password: RABBITMQ_PASS,
};
const amqpConnection = amqp.connect(connectionOpts);

async function produceMessage(order) {
  return amqpConnection
    .then(connection => connection.createChannel())
    .then(channel => {
      return channel.assertQueue(
        RABBITMQ_QUEUE_RETRY_GENERATE_AWB,
      )
        .then(ok => {
          const msgPut = {
            order: order.orderNumber,
          };

          const putQueue = channel.sendToQueue(
            RABBITMQ_QUEUE_RETRY_GENERATE_AWB,
            Buffer.from(JSON.stringify(msgPut)),
          );

          const msgLog = `ORDER: ${order.orderNumber}`;
          logger.info(
            `[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - SUCCESS - ${msgLog} has been put in the queue`,
          );

          return putQueue;
        });
    })
    .catch(error => {
      // eslint-disable-next-line no-console
      console.error(error);
      logger.error(
        '[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - ERROR - ',
        error,
      );
    });
}

async function retrieveOrders_generateAWBError() {
  const orders = await models.Order.findAll({
    where: {
      generateAwbStatus: 'ERROR',
      orderStatusLatest: [PROCESSING],
    },
  });

  return orders;
}

const orderList = [retrieveOrders_generateAWBError()];

async function mapper(orders) {
  if (isCancelled) return;
  try {
    if (Array.isArray(orders) && orders.length > 0) {
      const results = await pMap(orders, async order => {
        await produceMessage(order);
        return order.orderNumber;
      }, { concurrency });

      logger.info(`[JOB-RETRY-GENERATE-AWB] - SUCCESS - Orders to retry: ${results}`);

      return results;
    }

    return null;
  } catch (error) {
    logger.error('[JOB-RETRY-GENERATE-AWB] - ERROR - ', error);
  }
}

if (parentPort) {
  parentPort.once('message', message => {
    if (message === 'cancel') isCancelled = true;
  });
}

(async () => {
  await pMap(orderList, mapper, { concurrency });
  (await amqpConnection).close();

  if (parentPort) parentPort.postMessage('done');
  else process.exit(0);
})();

For example I have 3 data:

const orders = [
{ orderNumber: 'INV-001' },
{ orderNumber: 'INV-002' },
{ orderNumber: 'INV-003' }
];

const msgLog = `ORDER: ${order.orderNumber}`;

logger.info(
            `[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - SUCCESS - ${msgLog} has been put in the queue`,
          );

the result is ONLY logged:
[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - SUCCESS - INV-001 has been put in the queue

and

[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - SUCCESS - INV-002 has been put in the queue
[JOB-RETRY-GENERATE-AWB][PRODUCE-MQ] - SUCCESS - INV-003 has been put in the queue

never logged

Please help me

Thank you

[shadowgate15]

Node.js Worker does some weird things with console. Look at this to understand more.

To add to this, if for some reason the worker is exited before the console calls, from inside the worker, then it will not print them to the console.

It is better to use parentPort.postMessage(). There is a workerMessageHandler option in config for just this reason.

[prinarjayaoka]

Hi @shadowgate15 ,

Yeaa! it works! Thank you very much!

Yeaa parenPort.postMessage() is very very new thing for me. Now I can logging normally to cloudwatchlog via workerMessageHandler

Sorry for late inform and reply.