Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
dschnare opened this issue Jul 11, 2023 · 1 comment · Fixed by #830 · May be fixed by #827
Closed

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

dschnare opened this issue Jul 11, 2023 · 1 comment · Fixed by #830 · May be fixed by #827
Assignees
@cindy-peng
Labels
api: logging Issues related to the googleapis/nodejs-logging-winston API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@dschnare
Copy link

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
    })
  ]
})
  1. 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' })
})
  1. 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:

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
@dschnare dschnare added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. labels Jul 11, 2023
@product-auto-label product-auto-label bot added the api: logging Issues related to the googleapis/nodejs-logging-winston API. label Jul 11, 2023
@cindy-peng cindy-peng mentioned this issue Nov 6, 2023
Open
4 tasks
@cindy-peng cindy-peng mentioned this issue Nov 13, 2023
Merged
4 tasks
@cindy-peng
Copy link
Contributor

cindy-peng commented Nov 13, 2023 •
edited

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@cindy-peng cindy-peng

Labels
api: logging Issues related to the googleapis/nodejs-logging-winston API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Milestone
No milestone
3 participants
@dschnare @daniel-sanche @cindy-peng