[service-bus] docs.microsoft.com sample reporting "AMQP connection closed"

[richardpark-msft]

The sample: https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-nodejs-how-to-use-queues

Customer, in email thread, is reporting that the sample, prior to receiving all messages, reports "The underlying AMQP connection is closed". The sample itself only waits 5 seconds and the reported errors reports an errorSource of complete. These probably indicate the issue is related to auto complete, as far as the error.

However, only receiving 3 messages within 5 seconds might point to a further problem. I need to investigate and see if we need to reasonably bump that up in the sample to match reality a bit more and also see if we like how the error message is reported. We might need to coordinate the "connection is closing" event with the individual settlement methods.

(original issue: MicrosoftDocs/azure-docs#75397)

[richardpark-msft]

I've repro'd this (intermittently) by connecting to a not-in-Redmond Service Bus.

The issue appears to be that the client is closed but our auto-complete logic continues to run (or at least, it's finishing at the time when we're closed). What's interesting is that the exception in my repro throws from the management client - this would indicate that we noticed the link was closed and attempted to settle using our backup settlement method.

The behavior as it is today seems bad because you can't easily reason about when a receiver is no longer "active" (meaning, no longer doing work). We need to properly coordinate the receiver being closed by the user with any outstanding settlement requests and cancel them.

[richardpark-msft]

Some more diagnostics:

There was a delay on the application closing, even after the service client was closed:

azure:service-bus:receiver:verbose [connection-1|streaming:customerqueue1-25bf84f2-68f8-b046-b52a-309c92ae0ea7] Disposition for delivery id: 6, did not complete in 60000 milliseconds. Hence rejecting the promise with timeout error.
azure:core-amqp:verbose [connection-1] Error occurred for 'settlement' in attempt number 1: ServiceBusError: ServiceUnavailableError: Operation to settle the message has timed out. The disposition of the message may or may not be successful
    at translateServiceBusError (<src>\node_modules\@azure\service-bus\dist\index.js:4572:16)
    at Timeout._b [as _onTimeout] (<src>\node_modules\@azure\service-bus\dist\index.js:6593:35)
    at listOnTimeout (internal/timers.js:531:17)
    at processTimers (internal/timers.js:475:7) {
  name: 'ServiceBusError',
  retryable: true,
  info: undefined,
  code: 'GeneralError'
}
azure:core-amqp:verbose [connection-1] Sleeping for 30000 milliseconds for 'settlement'.

and then afterwards:

azure:core-amqp:verbose [connection-1] Error occurred for 'settlement' in attempt number 2: Error: The underlying AMQP connection is closed.
    at throwErrorIfConnectionClosed (<src>\node_modules\@azure\service-bus\dist\index.js:4881:23)
    at ManagementClient.<anonymous> (<src>\node_modules\@azure\service-bus\dist\index.js:5575:13)
    at Generator.next (<anonymous>)
    at <src>\node_modules\tslib\tslib.js:117:75
    at new Promise (<anonymous>)
    at Object.__awaiter (<src>\node_modules\tslib\tslib.js:113:16)
    at ManagementClient.updateDispositionStatus (<src>\node_modules\@azure\service-bus\dist\index.js:5574:22)
    at <src>\node_modules\@azure\service-bus\dist\index.js:6911:18
    at Generator.next (<anonymous>)
    at <src>\node_modules\tslib\tslib.js:117:75

These are all occurring way too late so it appears we might be missing some cleanup when the receiver has been closed.

[richardpark-msft]

Another little odd tidbit from the logs:

> Receiver closed
> Closing client
azure:service-bus:connection:verbose [connection-1] Permanently closing the amqp connection on the client.
azure:service-bus:connection:verbose [connection-1] Permanently closing 0 senders.
azure:service-bus:connection:verbose [connection-1] Permanently closing 1 receivers.

Note that at this point we have closed the receiver. I would not have expected the connection to still see one in it's map (it might be that we don't clean it up at that point).

(UPDATE: this set of log messages appear to be an unrelated symptom to this issue, and was fixed by #15890)

[richardpark-msft]

Leaving a last note on this, as I'm stepping away as maintainer of this particular package:

From what I can tell what we're running up against is the fact that close() is not "graceful" - it does not attempt to look at what activity is currently in process. This means that any in-process activity is going to be disrupted. This has always been the behavior of close, across all the other SDKs in Service Bus as well. The fix, for our sample, is correct in that it leaves enough time for the simple demo-behavior to work.

So for now I'm not sure, beyond adjusting the sample, if we want to address anything here. I'll leave this open for @chradek to decide if we should do more.

[jeremymeng]

I agree with @richardpark-msft. The sample fix is enough and at this point there are no work planned here. Closing