errorLogger when metaField=nulll

[jehanzebqayyum]

The errorLogger does not log anything when metaField is set to null.

app.use( expressWinston.errorLogger({ winstonInstance: logger, metaField: null }) );

[yinzara]

That causes the log metadata to be placed at the root of the log entry (see the read me) but depending on the transports you're using, this might not be what you want. What is the rest of your configuration?

[jehanzebqayyum]

hi,

The rest of configuration, json format, console and kafka transports.

[yinzara]

The kafka transport expects log messages to have the metadata of the log messages at the "meta" property of the log entry (the default behavior of express-winston when you don't set the metaField). By setting the "metaField" to null you put it at the root of the log entry (see the readme of express-winston for the use of this field) and would be ignored by kafka. This is used for other transports like the Stackdriver transport which expect additional metadata to be at the root of the log entry. Why are you setting it to null?

[jehanzebqayyum]

Strange! the kafka transport does pick up the messages cleanly without meta (i.e. from root message) in case of req/resp logger. Whereas the error logger does not log full details/meta fields when metaField=null.

I just wanted to have things less nested when received in ELK to match the pattern with other winston logs which are without meta

Best Regards, Jehanzeb Qayyum +971 52 898 2285

On Sun, 1 Mar 2020 at 22:01, Matthew Morrissette [email protected] wrote:

The kafka transport expects log messages to have the metadata of the log messages at the "meta" property of the log entry (the default behavior of express-winston when you don't set the metaField). By setting the "metaField" to null you put it at the root of the log entry (see the readme of express-winston for the use of this field) and would be ignored by kafka. Why are you setting it to null?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/bithavoc/express-winston/issues/236?email_source=notifications&email_token=ABJV6SWONMWHRKRUPNGMYJDRFKPHDA5CNFSM4K3BPMXKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENNGDIA#issuecomment-593125792, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABJV6SSQBMQRTZOY7JDZR6TRFKPHDANCNFSM4K3BPMXA .

[yinzara]

Hmmm well I might be wrong then. That seems very odd behavior to me, but I can't see any difference in the coding of the metadata mapping for errors vs normal request logging. Without more detailed information about your configuration and examples of how it's logging, I don't know how I can help you anymore.

[jehanzebqayyum]

export const logTransports = [
  new transports.Console(),
  new transports.WinstonKafkaTransport({
    kafkaClient: {
      kafkaHost: process.env.ELK_KAFKA_HOSTS,
      clientId: 'winston-kafka-logger'
    },
    topic: process.env.ELK_KAFKA_TOPIC
  })
];

export const logFormat = format.combine(format.timestamp(), format.json(), format.prettyPrint());

export const logger = createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: logFormat,
  transports: logTransports
});


app.use(
  expressWinston.logger({
    winstonInstance: logger,
    msg: 'service',
    responseWhitelist: ['body', 'statusCode', 'statusMessage', 'headers'],
    requestWhitelist: [
      'hostname',
      'ip',
      'method',
      'secure',
      'protocol',
      'path',
      'url',
      'query',
      'headers'
    ],
    metaField: null

    /* skip: (req, res) => {
      return res.statusCode === 200;
    } */
  })
);

//express routes

//error logger
app.use(
  expressWinston.errorLogger({
    winstonInstance: logger
    //metaField: null //does not log anything
  })
);

// Global express error handler

[yinzara]

If you remove the metaField from the errorLogger (like you have it), do you start to get metadata under the "meta" field? Do you have an example? I'm reading through the code and I can't find anything that varies between the two.

[jehanzebqayyum]

as of now i commented metaField: null, and its logging the error stats/details under meta. If i un-comment it will not log an error entry . I will post the 2 example logs (with/without metaField=null).

[jehanzebqayyum]

Without metaField=null { meta: { error: Error: baddddd at index.js:126:9 ..., level: 'error', message: 'uncaughtException: baddddd\n' + 'Error: baddddd\n' + ' at index.js:126:9\n' + ' ...', exception: true, date: 'Tue Mar 03 2020 12:27:20 GMT+0400 (Gulf Standard Time)', process: { pid: 12812, uid: null, gid: null, cwd: 'backend', execPath: 'c:\\nvm\\root\\node.exe', version: 'v12.14.0', argv: [ 'node', 'index.js' ], memoryUsage: { rss: 111165440, heapTotal: 83271680, heapUsed: 39301544, external: 1949438 } }, os: { loadavg: [ 0, 0, 0 ], uptime: 3029658 }, trace: [ { column: 9, file: 'index.js', function: null, line: 126, method: null, native: false }, { column: 5, file: 'layer.js', function: 'Layer.handle [as handle_request]', line: 95, method: 'handle [as handle_request]', native: false }, { column: 13, file: 'route.js', function: 'next', line: 137, method: null, native: false }, { column: 3, file: 'route.js', function: 'Route.dispatch', line: 112, method: 'dispatch', native: false }, { column: 5, file: 'layer.js', function: 'Layer.handle [as handle_request]', line: 95, method: 'handle [as handle_request]', native: false }, { column: 22, file: 'index.js', function: null, line: 281, method: null, native: false }, ], req: { url: '/health', headers: { host: 'localhost:4000', connection: 'keep-alive', 'upgrade-insecure-requests': '1', 'user-agent': 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36', 'sec-fetch-user': '?1', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9', 'sec-fetch-site': 'none', 'sec-fetch-mode': 'navigate', 'accept-encoding': 'gzip, deflate, br', 'accept-language': 'en-GB,en-US;q=0.9,en;q=0.8', 'if-none-match': 'W/"f-RQ8OySFd+KR+AvtJ7qImjtT0D/0"' }, method: 'GET', httpVersion: '1.1', originalUrl: '/health', query: {} } }, level: 'error', message: 'middlewareError', timestamp: '2020-03-03T08:27:20.375Z' } { req: { hostname: 'localhost', ip: '::1', method: 'GET', secure: false, protocol: 'http', path: '/health', url: '/health', query: {}, headers: { host: 'localhost:4000', connection: 'keep-alive', 'upgrade-insecure-requests': '1', 'user-agent': 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36', 'sec-fetch-user': '?1', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9', 'sec-fetch-site': 'none', 'sec-fetch-mode': 'navigate', 'accept-encoding': 'gzip, deflate, br', 'accept-language': 'en-GB,en-US;q=0.9,en;q=0.8', 'if-none-match': 'W/"f-RQ8OySFd+KR+AvtJ7qImjtT0D/0"' } }, res: { body: '<!DOCTYPE html>\n' + '<html lang="en">\n' + '<head>\n' + '<meta charset="utf-8">\n' + '<title>Error</title>\n' + '</head>\n' + '<body>\n' + '<pre>Error: baddddd<br> &nbsp; &nbsp;at ' + '</body>\n' + '</html>\n', statusCode: 500, statusMessage: 'Internal Server Error' }, responseTime: 134, level: 'info', message: 'service', timestamp: '2020-03-03T08:27:20.436Z' }

With metaField=null

{ req: { hostname: 'localhost', ip: '::1', method: 'GET', secure: false, protocol: 'http', path: '/health', url: '/health', query: {}, headers: { host: 'localhost:4000', connection: 'keep-alive', 'cache-control': 'max-age=0', 'upgrade-insecure-requests': '1', 'user-agent': 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36', 'sec-fetch-user': '?1', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9', 'sec-fetch-site': 'none', 'sec-fetch-mode': 'navigate', 'accept-encoding': 'gzip, deflate, br', 'accept-language': 'en-GB,en-US;q=0.9,en;q=0.8' } }, res: { body: '<!DOCTYPE html>\n' + '<html lang="en">\n' + '<head>\n' + '<meta charset="utf-8">\n' + '<title>Error</title>\n' + '</head>\n' + '<body>\n' + '<pre>Error: baddddd<br> &nbsp; &nbsp;at ' + '</body>\n' + '</html>\n', statusCode: 500, statusMessage: 'Internal Server Error' }, responseTime: 81, level: 'info', message: 'service', timestamp: '2020-03-03T08:32:35.735Z' }

As you notice the error logger did not log anything in 2nd case

[mi-mazouz]

any update on this? Same issue

[xiaoina]

same issue for me

[JohnLindahlTech]

Ok I have found the issue, and a fix, but not the reason.

lets begin with the fix: add/set the following to your config:

metaField: null,
blacklistedMetaFields: ['exception'],

My investigation so far (which I am gonna drop cause this is good enough for me): Q: So what is exception? A: it's just a boolean (specifically true every time since it is an error).

Q: Is it the key or the value that is the problem? A: well.. I do not know

Let me elaborate on the last answer I have tried the following with a custom error-extractor:

• exception: 'true' <- string, works ✅
• exception: 'false' <- string, works ✅
• exception: true <- boolean, broken 🛑
• exception: false <- boolean, works ✅
• exception2: true <- boolean, works ✅

So assuming you do not need the specific exception prop just blacklist it and get it working!