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

Aberta Para iniciantes
  • Algo errado?
#9,853 0 comentários 0 reações 0 responsáveis Ver no GitHub

Mantenedores costumam responder em até 1 dia

Ninguém assumiu esta issue ainda.

Avaliação

Dificuldade
2/5
Tempo estimado
1-3 horas
Facilidade para iniciantes
82/100
Tipo de issue
Bug
Clareza
Claramente especificada
Status de atividade
Ativa
Stack de tecnologia
node.js, typescript
Domínio
backend, observability

Direção de pesquisa

Leia handwritten/pubsub/src/telemetry-tracing.ts próximo a createAckRpcSpan e createModackRpcSpan e, em seguida, confira o fluxo da fila descrito em handwritten/pubsub/src/message-queues.ts e subscriber.ts. Reproduza o caso do span encerrado com o gist vinculado ou um teste focado equivalente. O trabalho estará concluído quando o tracing de ack e modack evitar chamar métodos em spans encerrados e o teste confirmar que o SDK não registra mais o erro.

Escrita pelo modelo de indexação a partir do texto da issue.

Descrição

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.

Linguagem predominante
TypeScript
Estrelas
3.2k
Forks
732
Merge médio
3d 7h
PRs com merge (30d)
117

Preparar o ambiente

Primeiros passos

  1. Leia a issue inteira e depois o guia de contribuição do projeto.
  2. Comente na issue dizendo que vai assumir — evita que duas pessoas façam o mesmo trabalho.
  3. Faça um fork do repositório e trabalhe em uma branch.
  4. Abra um pull request que referencie o número da issue.

Mais de googleapis/google-cloud-node

Todas as issues de googleapis/google-cloud-node

Issues semelhantes

Mais issues de TypeScript

Receba novas issues na sua caixa de entrada

Um resumo curto de issues do GitHub para quem está começando.