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

handwritten/pubsub/src/telemetry-tracing.tsでcreateAckRpcSpanとcreateModackRpcSpanの周辺を読み、その後、handwritten/pubsub/src/message-queues.tsとsubscriber.tsに記載されたキューの流れを確認してください。リンクされたgist、または同等の焦点を絞ったテストで、終了済みspanのケースを再現してください。ackとmodackのトレーシングが終了済みspanのメソッドを呼び出さず、SDKがエラーをログに記録しなくなったことをテストで確認できれば完了です。

Please make sure you have searched for information in the following guides.

• Search the issues already opened: https://github.com/GoogleCloudPlatform/google-cloud-node/issues
• Check the API's issue tracker (related, but publisher-side only: googleapis/nodejs-pubsub#2110, googleapis/nodejs-pubsub#2119)

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.