is there a way to pass a 'meta' object to winston through morgan?

[rconstantine]

I'm using Morgan for the HTTP logging and Winston wraps it. There is no explicit link between the two other than setting up the 'stream' option. Winston allows for a 'meta' object that can contain additional fields beyond the message and level. All of my logs except the Morgan ones contain metadata, like the username of the person triggering the leg event (or SYSTEM if not a user), and I'd like to add the same kind of thing for Morgan logs going to Winston. Any ideas?

[dougwilson]

So morgan is just a text logger and writes just a string to a stream for each log entry. I'm not sure what you're really talking about, so hard to answer more than that. Perhaps a code example would help clarify.

[rconstantine]

OK, that means there's no option. That's OK. The data is still available, I just can't parse it easily. I'll have to consider formatting as JSON. Thanks for the reply.

[Uko]

@rconstantine did you find a nice solution? Because I need to log objects (yes, like JS objects, not text), and I'm considering to hack Morgan to be able to specify a function that should be executed for each obtained object. If you know about other solutions it would be nice to learn :)

[Uko]

Actually, it's really interesting. If there was no + '\n' in https://github.com/expressjs/morgan/blob/master/index.js#L130 it could be straightforward to do object logging.

[rconstantine]

I did figure it out, but unfortunately, I didn't note what thing did it. So the below might be an overkill answer.

First, my Morgan format is defined as this:

/**
 * Setup morgan format
 */
morgan.token('id', function (req) {
  return req.sessionID
});
morgan.token('statusMessage', function (req, res) {
  if (typeof req.flash === 'function' && typeof req.flash('error') !== 'undefined' && req.flash('error').length !== 0) {
    return req.flash('error').slice(-1)[0];
  } else {
    return res.statusMessage;
  }
});
let morganFormat2 = '{"status"\:":status","statusMessage"\:":statusMessage","sessionID"\:":id","remote"\:":remote-addr","method"\:":method","url"\:":url","http"\:":http-version","referrer"\:":referrer","agent"\:":user-agent","length"\:":res[content-length]"}';

I think that by making the above a JSON object, that's all I needed to get it to work. However, for completeness, in case I don't recall everything correctly, I'll include the other bits of my code below too.

I then have morgan use a stream from winston thus:

app.use(morgan(morganFormat2, { stream: winston.stream }));

This next part handles all non-morgan errors and is in my main app file, along with the above bits of code too. Or maybe morgan does use this - I can't remember. See how the format in each winston.error call is followed by a comma and then an object as second parameter. That second param is the meta object. I use the same format for all of my other winston calls in my code too, like info messages.

/**
 * error handler
 * error handling must be placed after all other app.use calls; https://expressjs.com/en/guide/error-handling.html
 */
app.use(function(err, req, res, next) {
  // won't catch 401 Unauthorized errors. See authenticate.js for 401s
  if (!err.statusCode) err.statusCode = 500; // Sets a generic server error status code if none is part of the err
  // let data = JSON.parse(req.user.dataValues.data);
  // ${data.flash.error[0]}

  if (typeof req.user !== 'undefined' && req.user !== null) {
    if (typeof req.user.dataValues === 'undefined') {
      winston.error(`${err.statusCode || 500} ${err.message} - SessionID: ${req.sessionID} (${req.user.displayName})\" ${req.ip} \"${req.method} ${req.originalUrl} HTTP/${req.httpVersion}\" \"${req.headers['referer']}\" \"${req.headers['user-agent']}\" \"${req.headers['content-length']}\"`,
        {username: req.user.sAMAccountName, sessionID: req.sessionID, ip: req.ip, referrer: req.headers['referer'], url: req.originalUrl, query: req.method});
    } else {
      winston.error(`${err.statusCode || 500} ${err.message} - SessionID: ${req.user.dataValues.sid} (${req.user.dataValues.username})\" ${req.ip} \"${req.method} ${req.originalUrl} HTTP/${req.httpVersion}\" \"${req.headers['referer']}\" \"${req.headers['user-agent']}\" \"${req.headers['content-length']}\"`,
        {username: req.user.dataValues.username, sessionID: req.dataValues.sid, ip: req.ip, referrer: req.headers['referer'], url: req.originalUrl, query: req.method});
    }
  } else {
    winston.error(`${err.statusCode || 500} ${err.message} - \" ${req.ip} \"${req.method} ${req.originalUrl} HTTP/${req.httpVersion}\" \"${req.headers['referer']}\" \"${req.headers['user-agent']}\" \"${req.headers['content-length']}\"`,
      {sessionID: req.sessionID, ip: req.ip, referrer: req.headers['referer'], url: req.originalUrl, query: req.method});
  }

  // full HTML response only sent for Postman
  if (err.shouldRedirect) {
    res.render('error', { error: err }) // Renders a error.html for the user
  } else {
    res.status(err.statusCode).json({"Message": err.message}); // If shouldRedirect is not defined in our error, sends our original err data
  }
});

I have a file, winstonConfig that contains this:

import winston          from 'winston';
import { WinstonSequelize } from './winstonSequelize'; // supposedly this isn't used, but removing it throws an error

const myFormat = winston.format.printf(info => {
  if (info.meta) {
    return `${info.timestamp} [${info.label}] - SessionID: ${info.meta.sessionID}- ${info.level}: ${info.message}`;
  } else {
    return `${info.timestamp} [${info.label}] ${info.level}: ${info.message}`;
  }
});

// From https://www.digitalocean.com/community/tutorials/how-to-use-winston-to-log-node-js-applications with changes
// Looks like we have to keep format within the transport definition in order to get colorization to work
// There is a mail transport we could use for critical events called winston-mail.
let transportOptions = {
  file: {
    name: 'info-file',
    level: 'info',
    filename: './logs/app.log',
    handleExceptions: true,
    maxsize: 5242880, // 5MB
    maxFiles: 5,
    format: winston.format.combine(
      winston.format.splat(),
      winston.format.timestamp(),
      winston.format.label({ label: 'YourAppNameHere' }),
      myFormat
    )
  },
  console: {
    name: 'debug-console',
    level: 'debug',
    handleExceptions: true,
    json: false,
    format: winston.format.combine(
      winston.format.colorize({
        all: true
      }),
      winston.format.timestamp(),
      winston.format.label({ label: 'YourAppNameHere' }),
      myFormat
    )
  },
  winstonSequelize: {
    name: 'Sequelize',
    level: 'info',
    handleExceptions: true,
    format: winston.format.combine(
      winston.format.splat(),
      winston.format.timestamp(),
      winston.format.label({ label: 'YourAppNameHere' }),
      myFormat
    )
  }
};

// instantiate a new Winston Logger with the settings defined above
let logger = winston.createLogger({
  levels: winston.config.syslog.levels,
  transports: [
    new winston.transports.File(transportOptions.file),
    new winston.transports.winSequelize(transportOptions.winstonSequelize)
  ],
  exitOnError: true, // do not exit on handled exceptions
});

if (process.env.NODE_ENV !== 'production') {
  logger.add(new winston.transports.Console(transportOptions.console));
}

// create a stream object with a 'write' function that will be used by `morgan`; morgan only handles HTTP errors
logger.stream = {
  write: function(message, encoding) {
    // console.log('inside here', message);
    // morgan adds a \n that we need to remove.
    let code = parseInt(message.substring(11,13));
    if (code < 299) {
      logger.info(message.substring(0,message.lastIndexOf('\n')));
    } else if (code < 399) {
      logger.notice(message.substring(0,message.lastIndexOf('\n')));
    } else if (code < 499) {
      logger.error(message.substring(0,message.lastIndexOf('\n')));
    } else {
      logger.alert(message.substring(0,message.lastIndexOf('\n')));
    }
  },
};

// the following probably won't get to the DB because it isn't online when it is called
// logger.info('Starting logging service', {sessionID: 'SYSTEM', username: 'SYSTEM'});

module.exports = logger;

My winston sequelize transport. Here is where I manually handle what will be sent to my database.

//
// Winston transport for outputting to a database.
// Used "winston-sequelize" as a starting point, but pulled some things out
// and modified other things.
//
import Transport            from 'winston-transport';
import winston              from 'winston';
import { seq, Watchdog }    from '../db';

//
// ### function sequelize (options)
// Constructor for the Sequelize transport object.
//
export class WinstonSequelize extends Transport{
  constructor(options) {
    super(options);

    this.options = options || {};
    // Winston options
    this.name = options.name;
    this.level = options.level;

    // Sequelize options
    this.sequelize = seq;
    this.model = Watchdog;
  }

  //
  // ### function log (level, msg, [meta], callback)
  // #### @level {string} Level at which to log the message.
  // #### @msg {string} Message to log
  // #### @meta {Object} **Optional** Additional metadata to attach
  // #### @callback {function} Continuation to respond to when complete.
  // Core logging method exposed to Winston. Metadata is optional.
  //
  log(info, callback) {
    setImmediate(() => {
      this.emit('logged', info);
    });
    const logit = () => {
      const data = {
        msg: info.message,
        level: info.level
      };

      const meta = info.meta;

      if (typeof info.meta !== 'undefined') {
        if (meta && (typeof meta !== 'object')) {
          throw new Error("Meta information must be an object");
        } else {
          data.username   = !!meta.username ? meta.username : null;
          data.referrer   = !!meta.referrer ? meta.referrer : null;
          data.meta       = !!meta ? (!!meta.meta ? JSON.stringify(meta.meta) : JSON.stringify(meta)) : null;
          data.ip_address = !!meta.ip ? meta.ip : null;
          data.session_id = !!meta.sessionID ? meta.sessionID : null;
          data.route      = !!meta.route ? meta.route : null;
          data.query      = !!meta.query ? meta.query : null;
          data.body       = !!meta.body ? meta.body : null;
          data.host       = !!meta.host ? meta.host : null;
          data.url        = !!meta.url ? meta.url : null;
        }
      } else {
        // we probably have a morgan message. let's check!
        data.username     = 'SYSTEM';
        let morganJson    = JSON.parse(info.message);
        data.referrer     = morganJson.referrer;
        data.meta         = info.message;
        data.ip_address   = morganJson.ip;
        data.session_id   = morganJson.sessionID;
        data.query        = morganJson.method;
        data.url          = morganJson.url;
        data.msg          = morganJson.statusMessage;
      } // do not throw error if info.meta is undefined as it will not be defined for Morgan log messages
      data.created_at = new Date();

      this.model.create(data);

      callback();
    };

    return logit();
  }
}

//
// Define a getter so that `winston.transports.winSequelize`
// is available and thus backwards compatible.
//
winston.transports.winSequelize = WinstonSequelize;
module.exports = WinstonSequelize;

Lastly, is my database table definition:

import Sequelize from 'sequelize'

/**
 * Watchdog table definition
 *
 * id: The row ID
 * log_type: The reporting module or function
 * severity: One of several constants available in the errors/index.js file
 * username: The user who performed the action being logged
 * message: Any information that needs to be conveyed in this log such as before and after states of data
 * hostname: The URL/IP the user is from
 * path: The path in the program that originated the request
 * referrer: If there was a referring page, different from the path, it goes here
 *
 * @param seq
 * @return {void|Model|*}
 */
export default({ seq }) => {
  return seq.define('watchdog', {
    id: {
      type: Sequelize.INTEGER,
      primaryKey: true,
      autoIncrement: true
    },
    level: {
      type: Sequelize.STRING,
      allowNull: false
    },
    msg: {
      type: Sequelize.TEXT,
      unique: false,
      allowNull: false
    },
    username: {
      type: Sequelize.STRING,
      allowNull: true
    },
    referrer: {
      type: Sequelize.STRING,
      allowNull: true
    },
    meta: {
      type: Sequelize.TEXT,
      allowNull: true
    },
    created_at: {
      type: Sequelize.DATE,
      allowNull: true
    },
    ip_address: {
      type: Sequelize.STRING,
      allowNull: true
    },
    session_id: {
      type: Sequelize.STRING,
      allowNull: true
    },
    route: {
      type: Sequelize.TEXT,
      allowNull: true
    },
    query: {
      type: Sequelize.TEXT,
      allowNull: true
    },
    body: {
      type: Sequelize.TEXT,
      allowNull: true
    },
    host: {
      type: Sequelize.TEXT,
      allowNull: true
    },
    url: {
      type: Sequelize.TEXT,
      allowNull: true
    }
  },
  {
    timestamps: false
  });
}

[tonyxiao]

The simplest solution would be to change this one line

https://github.com/expressjs/morgan/blob/master/index.js#L130

from stream.write(line + '\n') to stream.write(line + '\n', req, res). That way additional context related to the request can be passed to the stream object if needed. Would anyone object to a fork?

[dougwilson]

Hi @tonyxiao you're certainly welcome to fork it. As far as your proposal goes, the .write function takes the values defined by the Node.js stream interface: https://nodejs.org/dist/latest-v10.x/docs/api/stream.html#stream_writable_write_chunk_encoding_callback

That is, the signature is .write(chunk[, encoding][, callback]). You would end up passing the req object as the encoding and the res object as the callback in your case.