googleapis / nodejs-logging-winston

Node.js client integration between Stackdriver Logging and Winston.
https://cloud.google.com/logging/
Apache License 2.0
105 stars 50 forks source link

OpenTelemetry issues; timestamp drift, and LOGGING_SAMPLED_KEY is not treated as boolean #802

Closed dschnare closed 9 months ago

dschnare commented 1 year ago

Environment details

Steps to reproduce

  1. Create a simple logger

    const logger = Winston.createLogger({
    level: 'info',
    transports: [
    new Winston.transports.Console({
      format: Winston.format.combine(
        Winston.format.timestamp(),
        Winston.format.simple()
     )
    }),
    new LoggingWinston({
      format: Winston.format.combine(
        Winston.format.timestamp(),
        Winston.format.json()
      ),
      serviceContext: {
        service: config.serviceName,
        version: config.serviceVersion
      },
      projectId: config.googleCloudProjectId
    })
    ]
    })
  2. Use logger in a simple express app.

    
    const app = express()
    const logger = require('./logger')

app.get('/hello', (req, res) => { logger.info('hello called', { stuff: 'yep' }) res.status(200).json({ message: 'hello' }) })


3. Notice in Cloud Logging and the console that the timestamps differ.

This has a big impact when using OpenTelemetry since the link to "View Logs" relies on the log entries having a timestamp that lies within the timespan of a span during a trace. There is often a drift of a few 100ms in Cloud Logging vs the timespans in Cloud Trace.

By investigating the code I found that `info.timestamp` is intended to be a `Date` instance in `LoggingCommon#log`. So to remedy I had to do this:
```js
const logger = Winston.createLogger({
  level: 'info',
  format: Winston.format.timestamp(),
  transports: [
    new Winston.transports.Console({
      format: Winston.format.simple()
    }),
    new LoggingWinston({
      format: Winston.format.combine(
        // Ensure timestamp is a Date instance
        Winston.format((info) => {
          info.timestamp = new Date(info.timestamp)
          return info
        })(),
        Winston.format.json()
      ),
      serviceContext: {
        service: config.serviceName,
        version: config.serviceVersion
      },
      projectId: config.googleCloudProjectId
    })
  ]
})

The code that expects timestamp to be a Date is within LoggingCommon:

image

An additional issue is that the key LoggingWinston.LOGGING_SAMPLED_KEY should be expected to be a boolean, but the LoggingCommon class expects it to be a string like "1". In OpenTelemetry this is stored in the traceFlags of the span context as a number, not a string. And typically we can convert to boolean via span.spanContext().traceFlags === OpenTelemetry.TraceFlags.SAMPLED. It's really odd to have this documented as needing to be a boolean but in the code it expects a string.

As a remedy I had to set this key to String(span.spanContext().traceFlags).

image
cindy-peng commented 9 months ago

Hi @dschnare, Thank you for reporting the issue. I was able to repro the issue and I have sent out PRs to address the two concerns mentioned above:

  1. Timestamps drift in logging library: https://github.com/googleapis/nodejs-logging-winston/pull/827 2.LoggingWinston.LOGGING_SAMPLED_KEY expecting boolean value: https://github.com/googleapis/nodejs-logging-winston/pull/830