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

[dschnare]

Environment details

• OS: OSX Ventura 13.4.1
• Node.js version: v14.18.0
• npm version: 7.21.1
• @google-cloud/logging-winston version: 5.3.0

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:

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:

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).

[cindy-peng]

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: fix: Fix timestamp drift due to using instanceof typeguard #827
   2.LoggingWinston.LOGGING_SAMPLED_KEY expecting boolean value: fix: Fix trace_sampled type to be consistent with API documentation #830