expressWinston.logger({ msg }) prints plaintext function instead of return value

[awwong1]

I'm having issues with printing out messages when I pass in a function, instead of a string in the options.msg parameter.

Dependencies

Verified this happening on Node v9.2.0 (stable) and Node v8.10.0 (lts).

// package.json dependencies
{
    "express": "^4.16.2",
    "express-winston": "^2.5.0",
    "winston": "^2.4.0"
}

Issue

Given the following configuration:

const winstonLoggerConfig = {
  transports: [
    new winston.transports.Console({
      json: true,
      colorize: false
    })
  ],
  meta: true,

  // passing in a function, instead of a string
  msg: (req, res) => {
    const operationName = (req.body || {}).operationName || "NO-OP";
    return `${res.statusCode} ${req.method} ${req.url} ${operationName} ${res.responseTime}ms`;
  },
  // aside. also verified that function() {} fails as well

  requestWhitelist: [...expressWinston.requestWhitelist, "body"],
  expressFormat: false,
  colorize: false
};

// ...
app.use(expressWinston.logger(winstonLoggerConfig));

Expected Output

I expected to see "message": "200 POST /graphql SignInMutation 338ms":

{
  "res": {
    "statusCode": 200
  },
  "req": {
    "url": "/graphql",
    "headers": {
      "host": "localhost:3000",
      "connection": "keep-alive",
      "content-length": "395",
      "accept": "*/*",
      "origin": "http://localhost:3001",
      "authorization": "null",
      "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.186 Safari/537.36",
      "content-type": "application/json",
      "dnt": "1",
      "referer": "http://localhost:3001/sign-in",
      "accept-encoding": "gzip, deflate, br",
      "accept-language": "en-CA,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"
    },
    "method": "POST",
    "httpVersion": "1.1",
    "originalUrl": "/graphql",
    "query": {},
    "body": {
      "operationName": "SignInMutation",
      "variables": {
        "email": "test@test.tld",
        "password": "supersecret"
      },
      "query": "mutation SignInMutation($email: String!, $password: String!) {\n  signinUser(email: {email: $email, password: $password}) {\n    token\n    user {\n      _id\n      username\n      createdAt\n      updatedAt\n      email\n      emailVerified\n      __typename\n    }\n    __typename\n  }\n}\n"
    }
  },
  "responseTime": 338,
  "level": "info",
  "message": "200 POST /graphql SignInMutation 338ms"
}

Actual Output

Instead I see "message": "(req, res) => {\n const operationName = (req.body || {}).operationName || \"NO-OP\";\n return `${res.statusCode} ${req.method} ${req.url} ${operationName} ${res.responseTime}ms`;\n }" :

{
  "res": {
    "statusCode": 200
  },
  "req": {
    "url": "/graphql",
    "headers": {
      "host": "localhost:3000",
      "connection": "keep-alive",
      "content-length": "395",
      "accept": "*/*",
      "origin": "http://localhost:3001",
      "authorization": "null",
      "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.186 Safari/537.36",
      "content-type": "application/json",
      "dnt": "1",
      "referer": "http://localhost:3001/sign-in",
      "accept-encoding": "gzip, deflate, br",
      "accept-language": "en-CA,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"
    },
    "method": "POST",
    "httpVersion": "1.1",
    "originalUrl": "/graphql",
    "query": {},
    "body": {
      "operationName": "SignInMutation",
      "variables": {
        "email": "test@test.tld",
        "password": "supersecret"
      },
      "query": "mutation SignInMutation($email: String!, $password: String!) {\n  signinUser(email: {email: $email, password: $password}) {\n    token\n    user {\n      _id\n      username\n      createdAt\n      updatedAt\n      email\n      emailVerified\n      __typename\n    }\n    __typename\n  }\n}\n"
    }
  },
  "responseTime": 338,
  "level": "info",

  "message": "(req, res) => {\n    const operationName = (req.body || {}).operationName || \"NO-OP\";\n    return `${res.statusCode} ${req.method} ${req.url} ${operationName} ${res.responseTime}ms`;\n  }"
}

Links

• Commit hash: https://github.com/udia-software/udia-server/commit/d5dbcd5547f7696d916ceff07134c85502f5acdd
• TravisCI build showing logging errors: https://travis-ci.org/udia-software/udia-server/jobs/350503545

[awwong1]

Feature added in PR https://github.com/bithavoc/express-winston/pull/160

[rosston]

Closing because this is fixed in #160, which has been merged.