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

Offen Anfängerfreundlich
  • Stimmt etwas nicht?
#9,853 0 Kommentare 0 Reaktionen 0 zugewiesene Personen Auf GitHub ansehen

Maintainer antworten meist innerhalb von 1 Tag

Dieses Issue hat noch niemand übernommen.

Bewertung

Schwierigkeit
2/5
Geschätzter Aufwand
1-3 Stunden
Anfängerfreundlichkeit
82/100
Issue-Typ
Bug
Klarheit
Klar beschrieben
Aktivitätsstatus
Aktiv
Tech-Stack
node.js, typescript
Bereich
backend, observability

Rechercherichtung

Lies handwritten/pubsub/src/telemetry-tracing.ts im Bereich von createAckRpcSpan und createModackRpcSpan und prüfe anschließend den Queue-Ablauf, der in handwritten/pubsub/src/message-queues.ts und subscriber.ts beschrieben ist. Reproduziere den Fall mit dem beendeten Span anhand des verlinkten Gists oder eines gleichwertigen gezielten Tests. Die Aufgabe ist erledigt, wenn das Ack- und Modack-Tracing keine Methoden auf beendeten Spans aufruft und der Test bestätigt, dass das SDK den Fehler nicht mehr protokolliert.

Vom Indexierungsmodell aus dem Issue-Text verfasst.

Beschreibung

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.

Vorherrschende Sprache
TypeScript
Sterne
3.2k
Forks
732
Ø Merge
3 T. 7 Std.
Gemergte PRs (30 T.)
117

Entwicklungsumgebung

Erste Schritte

  1. Lesen Sie das ganze Issue und danach den Beitragsleitfaden des Projekts.
  2. Schreiben Sie ins Issue, dass Sie es übernehmen — das erspart doppelte Arbeit.
  3. Forken Sie das Repository und arbeiten Sie in einem Branch.
  4. Öffnen Sie einen Pull Request, der die Issue-Nummer nennt.

Mehr aus googleapis/google-cloud-node

Alle Issues in googleapis/google-cloud-node

Ähnliche Issues

Weitere Issues zu TypeScript

Neue Issues direkt in Ihr Postfach

Eine kurze Übersicht über anfängerfreundliche GitHub-Issues.