pubsub: "Operation attempted on ended Span" when a modack is flushed after the message was acked

Abierto Apto para principiantes
  • ¿Algo no está bien?
#9,853 0 comentarios 0 reacciones 0 asignados Ver en GitHub

Los mantenedores suelen responder en 1 día

Nadie ha tomado este issue todavía.

Evaluación

Dificultad
2/5
Tiempo estimado
1-3 horas
Aptitud para principiantes
82/100
Tipo de issue
Error
Claridad
Bien especificado
Estado de actividad
Activo
Stack tecnológico
node.js, typescript
Área
backend, observability

Línea de trabajo

Lee handwritten/pubsub/src/telemetry-tracing.ts alrededor de createAckRpcSpan y createModackRpcSpan, y luego revisa el flujo de la cola descrito en handwritten/pubsub/src/message-queues.ts y subscriber.ts. Reproduce el caso del span finalizado con el gist enlazado o con una prueba específica equivalente. El trabajo estará terminado cuando el tracing de ack y modack evite llamar a métodos en spans finalizados y la prueba confirme que el SDK ya no registra el error.

Escrito por el modelo de indexación a partir del texto del issue.

Descripción

api: pubsub
Please make sure you have searched for information in the following guides.
Library Name

@google-cloud/pubsub (reproduced on 6.0.1 and 6.4.1)

A screenshot that you have tested with "Try this API".

N/A. This is a client-side bug in the library's OpenTelemetry instrumentation. No API call is needed to reproduce it.

Link to the code that reproduces this issue. A link to a public Github Repository or gist with a minimal reproduction.

https://gist.github.com/tmair/b9c1cd2b558e40eb8423566580d0a244

A step-by-step description of how to reproduce the issue, based on the linked reproduction.
  1. npm install && npm start
  2. The repro registers an SDK BasicTracerProvider, enables pubsub tracing, starts a subscribe span and ends it. This simulates a message that was acked while a modack for it was still queued. It then calls PubsubSpans.createModackRpcSpan([subscribeSpan], ...), which is what ModAckQueue._sendBatch does when the queue flushes.
  3. The OpenTelemetry SDK logs:
Cannot execute the operation on ended Span {traceId: ..., spanId: ...} Error: Operation attempted on ended Span {traceId: ..., spanId: ...}
    at SpanImpl._isSpanEnded (.../@opentelemetry/sdk-trace/build/src/Span.js:342:27)
    at SpanImpl.addLink (.../@opentelemetry/sdk-trace/build/src/Span.js:170:18)
    at .../@google-cloud/pubsub/build/src/telemetry-tracing.js:421:23
    at Array.forEach (<anonymous>)
    at PubsubSpans.createModackRpcSpan (...)

We see this in production on a subscriber created with enableOpenTelemetryTracing: true and @opentelemetry/sdk-node (sdk-trace 2.11.0). It happens for messages whose processing takes long enough to get a lease extension. The stack trace from production:

Error: Operation attempted on ended Span {traceId: 8d525b04ad08368f161db86c3d9c950d, spanId: 6419191f508e8c82}
    at SpanImpl._isSpanEnded (/app/otel-instrumentation/node_modules/@opentelemetry/sdk-trace/build/src/Span.js:342:27)
    at SpanImpl.addLink (/app/otel-instrumentation/node_modules/@opentelemetry/sdk-trace/build/src/Span.js:170:18)
    at /app/node_modules/@google-cloud/pubsub/build/src/telemetry-tracing.js:420:23
    at Array.forEach (<anonymous>)
    at PubsubSpans.createModackRpcSpan (/app/node_modules/@google-cloud/pubsub/build/src/telemetry-tracing.js:418:26)
    at /app/node_modules/@google-cloud/pubsub/build/src/message-queues.js:538:54
    at Array.map (<anonymous>)
    at ModAckQueue._sendBatch (/app/node_modules/@google-cloud/pubsub/build/src/message-queues.js:533:57)
    at async ModAckQueue.flush (/app/node_modules/@google-cloud/pubsub/build/src/message-queues.js:262:29)
A clear and concise description of what the bug is, and what you expected to happen.

The ack and modack queues flush independently, but both keep a reference to the message's subscribe span:

  1. The lease manager extends the deadline of a message that is still being processed. MessageQueue.add stores message.parentSpan as tracingSpan in the modack batch (message-queues.ts#L254).
  2. The handler calls message.ack(). Subscriber.ack waits only for the ack queue to flush and then calls message.endParentSpan() (subscriber.ts#L889-L892).
  3. The modack queue flushes afterwards. createModackRpcSpan calls m.addLink(...) on the subscribe span that has already ended (telemetry-tracing.ts#L602-L608).

The OpenTelemetry SDK rejects the addLink call and logs an error through diag. Nothing is thrown and the messages are acked correctly, but every affected message produces an error log entry, which shows up as an error group in Cloud Error Reporting. createAckRpcSpan uses the same pattern (telemetry-tracing.ts#L554-L560) and could hit the same problem for a span that ended in another way (e.g. nack or shutdown).

Expected: the library does not call methods on spans that it has already ended, so no errors are logged.

Suggested fix: skip spans that are no longer recording in createModackRpcSpan and createAckRpcSpan:

messageSpans.forEach(m => {
  if (m && isSampled(m) && m.isRecording()) {
    m.addLink({context: span.spanContext()});
  }
});

An SDK span returns isRecording() === false once it has ended, so this skips exactly the failing case. The link from the subscribe span to the RPC span is lost for those messages, but the subscribe span has already been exported at that point anyway.

A clear and concise description WHY you expect this behavior, i.e., was it a recent change, there is documentation that points to this behavior, etc. **

The OpenTelemetry specification does not allow changes to a span after end() has been called ("Implementations SHOULD ignore all subsequent calls to End and any other Span methods"), and the SDK reports such calls as errors. The library ends the subscribe span itself in Subscriber.ack, so it should not modify that span afterwards. The same class of bug was reported for the publisher side in googleapis/nodejs-pubsub#2110 and googleapis/nodejs-pubsub#2119.

Lenguaje dominante
TypeScript
Estrellas
3.2k
Forks
732
Merge medio
3 d 7 h
PR fusionados (30 d)
117

Preparar el entorno

Primeros pasos

  1. Lee el issue completo y luego la guía de contribución del proyecto.
  2. Comenta en el issue que vas a ocuparte — evita que dos personas hagan lo mismo.
  3. Haz un fork del repositorio y trabaja en una rama.
  4. Abre un pull request que haga referencia al número del issue.

Más de googleapis/google-cloud-node

Todos los issues de googleapis/google-cloud-node

Issues similares

Más issues de TypeScript

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.