Timestamps not making sense

[dschnare]

Hey guys, I'm wondering if anyone has had similar issues as this before.

I'm using automatic Nodejs instrumentation. I only enabled pg, http, express, and redis instrumentations. The web app works. However, after booting the app and running a few seeds and then looking at a few spans for a message puller (a worker process that pulls messages from a message queue), the span timings for SQL queries makes little sense.

Example 1:
This screenshot shows that a COMMIT occurs after the parent span ends. This is impossible in code because I added instrumentation for a wrapping function that does not end the span until all SQL and the transaction is done.

Example 2:
This screenshot shows that while connecting a BEGIN query was being executed. This is also impossible in code because the client is obtained and connected to first before any SQL is sent over the connection.

Is there something I'm missing? Besides the custom span creation to monitor our message workers, this is a vanilla OTEL installation, following the Nodejs automatic guide.

[dschnare]

I'm using Jaeger to view the traces when developing locally.

[dschnare]

Sorry for the fast reply, but I realize in the example I could make a single SQL query with BEGIN, and COMMIT included, but in practice the production code has abstractions around a transaction so the BEGIN and COMMIT will always occur as separate queries over the connection.

[Flarna]

Hmm, don't know what is going on here. The log message clock skew adjustment disable... seems to come from jaeger but this is likely not the problem just one more symptom.

Are you using @opentelemetry/instrumentation-pg to monitor PG or something else?

[dschnare]

I appreciate your time @Flarna. It's nice to have a sounding board/someone to help.

Yeah I'm using @opentelemetry/instrumentation-pg. I've used the Node SDK automated instrumentation approach. Here's my instrumentation entry point if this helps frame things. I ensure this is requires via the -r Node arg.

/*
Require this module only once. Configured by environment variables.
Easiest way to use this module is to require it by using the -r flag:
node -r ./instrumentation/instrument.js server.js
*/

const { NodeSDK } = require('@opentelemetry/sdk-node')
const { Resource } = require('@opentelemetry/resources')
const { gcpDetector } = require('@opentelemetry/resource-detector-gcp')
const { OTLPTraceExporter } = require('@opentelemetry/exporter-trace-otlp-http') // used by jaeegertracing.io
const { TraceExporter } = require('@google-cloud/opentelemetry-cloud-trace-exporter') // used by Google Cloud Trace
const { getNodeAutoInstrumentations } = require('@opentelemetry/auto-instrumentations-node')
const { SemanticResourceAttributes: ResourceAttributesSC } = require('@opentelemetry/semantic-conventions')
const { LoggingWinston } = require('@google-cloud/logging-winston')
const { config } = require('./config')

const sdk = new NodeSDK({
  spanLimits: {
    attributePerEventCountLimit: 50,
    attributeValueLengthLimit: 1024,
    eventCountLimit: 10
  },
  serviceName: config.serviceName,
  autoDetectResources: true,
  resourceDetectors: [
    config.useGoogleCloudTrace && gcpDetector
  ].filter(Boolean),
  resource: Resource.default().merge(
    new Resource({
      [ResourceAttributesSC.SERVICE_NAME]: config.serviceName,
      [ResourceAttributesSC.SERVICE_VERSION]: config.serviceVersion
    })
  ),
  traceExporter: (
    config.useGoogleCloudTrace
      ? new TraceExporter({
        projectId: config.googleCloudProjectId,
        resourceFilter: /.*/u
      })
      : new OTLPTraceExporter()
  ),
  instrumentations: [
    getNodeAutoInstrumentations({
      // Instrumentations that are needed
      '@opentelemetry/instrumentation-http': { enabled: true },
      '@opentelemetry/instrumentation-express': {
        enabled: true,
        // @ts-ignore
        ignoreLayersType: ['router', 'middleware', 'request_handler']
      },
      '@opentelemetry/instrumentation-pg': { enabled: true, requireParentSpan: true },
      '@opentelemetry/instrumentation-redis': { enabled: true, requireParentSpan: true },
      '@opentelemetry/instrumentation-winston': {
        enabled: true,
        logHook: (span, info) => {
          if (config.useGoogleCloudTrace) {
            delete info.span_id
            delete info.trace_id
            delete info.trace_flags
            info.service = config.serviceName
            info[LoggingWinston.LOGGING_TRACE_KEY] = `projects/${config.googleCloudProjectId}/traces/${span.spanContext().traceId}`
            info[LoggingWinston.LOGGING_SPAN_KEY] = span.spanContext().spanId
            // https://github.com/googleapis/nodejs-logging-winston/issues/802
            // NOTE: After reviewing the source code, this key has to be a string.
            info[LoggingWinston.LOGGING_SAMPLED_KEY] = String(span.spanContext().traceFlags)
          } else {
            span.addEvent(String(info.message || 'winston.log'), Object.fromEntries(
              // NOTE: After reviewing the soure code, property values cannot be objects,
              // but arrays are ok.
              Object.entries(info)
                .filter(([key]) => {
                  return ![
                    'message',
                    'service',
                    'span_id',
                    'trace_id',
                    'trace_flags',
                    'level',
                    'severity',
                    'timestamp',
                    LoggingWinston.LOGGING_TRACE_KEY,
                    LoggingWinston.LOGGING_SAMPLED_KEY,
                    LoggingWinston.LOGGING_SPAN_KEY
                  ].includes(key)
                })
                .map(([key, value]) => {
                  if (!Array.isArray(value) && value && typeof value === 'object') {
                    return [key, JSON.stringify(value, null, 2)]
                  } else {
                    return [key, value]
                  }
                })
            ))
          }
        }
      },
      // Instrumetnations that are not needed
      '@opentelemetry/instrumentation-amqplib': { enabled: false },
      '@opentelemetry/instrumentation-aws-lambda': { enabled: false },
      '@opentelemetry/instrumentation-aws-sdk': { enabled: false },
      '@opentelemetry/instrumentation-bunyan': { enabled: false },
      '@opentelemetry/instrumentation-cassandra-driver': { enabled: false },
      '@opentelemetry/instrumentation-connect': { enabled: false },
      '@opentelemetry/instrumentation-dataloader': { enabled: false },
      '@opentelemetry/instrumentation-dns': { enabled: false },
      '@opentelemetry/instrumentation-fastify': { enabled: false },
      '@opentelemetry/instrumentation-fs': { enabled: false },
      '@opentelemetry/instrumentation-generic-pool': { enabled: false },
      '@opentelemetry/instrumentation-graphql': { enabled: false },
      '@opentelemetry/instrumentation-grpc': { enabled: false },
      '@opentelemetry/instrumentation-hapi': { enabled: false },
      '@opentelemetry/instrumentation-ioredis': { enabled: false },
      '@opentelemetry/instrumentation-knex': { enabled: false },
      '@opentelemetry/instrumentation-koa': { enabled: false },
      '@opentelemetry/instrumentation-lru-memoizer': { enabled: false },
      '@opentelemetry/instrumentation-memcached': { enabled: false },
      '@opentelemetry/instrumentation-mongodb': { enabled: false },
      '@opentelemetry/instrumentation-mongoose': { enabled: false },
      '@opentelemetry/instrumentation-mysql2': { enabled: false },
      '@opentelemetry/instrumentation-mysql': { enabled: false },
      '@opentelemetry/instrumentation-nestjs-core': { enabled: false },
      '@opentelemetry/instrumentation-net': { enabled: false },
      '@opentelemetry/instrumentation-pino': { enabled: false },
      '@opentelemetry/instrumentation-redis-4': { enabled: false },
      '@opentelemetry/instrumentation-restify': { enabled: false },
      '@opentelemetry/instrumentation-router': { enabled: false },
      '@opentelemetry/instrumentation-socket.io': { enabled: false },
      '@opentelemetry/instrumentation-tedious': { enabled: false }
    })
  ]
})

sdk.start()

As a contrast here's a simple example that exhibits correct timestamps. No Postgres or SQL, just simulating simple logic and custom spans. So it does seem to be related to PG instrumentation and not my instrument abstraction. I haven't even gotten to HTTP tracing yet (just want to be able to trust the timestamps with PG first).

NOTE: instrument is the function as defined in my second comment above (way at the top).

instrument('helloDolly', {}, async () => {
  await instrument('sayHello', {}, async () => {
    await new Promise((resolve) => setTimeout(resolve, 1000))
    console.log('hello')
  })

  await instrument('sayGoodbye', {}, async () => {
    await new Promise((resolve) => setTimeout(resolve, 1000))
    console.log('goodbye')
  })

  await instrument('cleanup', {}, async () => {
    await new Promise((resolve) => setTimeout(resolve, 1000))

    await Promise.all([
      instrument('purgeNotes', {}, async () => {
        await new Promise((resolve) => setTimeout(resolve, 1000))
      }),
      instrument('purgeEvents', {}, async () => {
        await new Promise((resolve) => setTimeout(resolve, 1000))
      })
    ])
  })
}).then(() => {})

[Flarna]

@rauno56 This seems to be instrumentation-pg specific and you are listed as owner of this instrumentation. Any ideas what could cause this?
I have done a fast look but I haven't seen anything obvious that could explain this behavior

[dschnare]

Thanks @Flarna for raising this. These timestamp issues make instrumentation-pg much less useful.

@rauno56 if you could spare a a few minutes to review this it would be truly appreciated. Thanks for your help.

[bokhtiar-boo]

I'm encountering a similar issue where my request handler completes within a few seconds, but the root span shows a significantly longer duration. In several traces, I've noticed that while my request handler finishes processing in 6-7 seconds, the root span indicates a total time of over 100 seconds, with no additional spans to account for this extended duration. Do you have any suggestion about what might be causing this issue?