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

Ouverte Adaptée aux débutants
  • Quelque chose ne va pas ?
#9,853 0 commentaires 0 réactions 0 personnes assignées Voir sur GitHub

Les mainteneurs répondent en général sous 1 jour

Personne n'a encore pris cette issue.

Évaluation

Difficulté
2/5
Temps estimé
1-3 heures
Accessibilité débutants
82/100
Type d'issue
Bug
Clarté
Clairement spécifiée
Activité
Active
Stack technique
node.js, typescript
Domaine
backend, observability

Piste de recherche

Lis handwritten/pubsub/src/telemetry-tracing.ts autour de createAckRpcSpan et createModackRpcSpan, puis examine le flux de la file d’attente décrit dans handwritten/pubsub/src/message-queues.ts et subscriber.ts. Reproduis le cas du span terminé à l’aide du gist lié ou d’un test ciblé équivalent. Le travail est terminé lorsque le tracing d’ack et de modack évite d’appeler des méthodes sur des spans terminés et que le test confirme que le SDK ne consigne plus l’erreur.

Rédigé par le modèle d'indexation à partir du texte de l'issue.

Description

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.

Langage dominant
TypeScript
Étoiles
3.2k
Forks
732
Merge moyen
3 j 7 h
PR mergées (30 j)
117

Préparer son environnement

Par où commencer

  1. Lisez l'issue en entier, puis le guide de contribution du projet.
  2. Signalez en commentaire que vous la prenez — cela évite que deux personnes fassent le même travail.
  3. Forkez le dépôt et travaillez sur une branche.
  4. Ouvrez une pull request qui référence le numéro de l'issue.

Autres issues de googleapis/google-cloud-node

Toutes les issues de googleapis/google-cloud-node

Issues similaires

Plus d'issues TypeScript

Recevez les nouvelles issues par e-mail

Un résumé court des issues GitHub adaptées aux débutants.