[Service Bus] Stress/Spike Multiple Clients against Single Queue (Receiver kept open after message receive) (T1 scenario within P0)

[ramya0820]

• Package Name: ramya0820/perf-tests-azure-js-sdk-service-bus
• Package Version: 1.0.0
• Operating system: Windows 10
• nodejs
  • version: v10.14.2
• typescript
  • version: ts-node v8.0.2

Describe the bug
On running sample for 5000 clients, following observations were made:

• Encountered error

2019-03-21T01:25:37.915Z rhea-promise:connection [connection-1] connection got event: 'disconnected'. Re-emitting the translated context.
2019-03-21T01:25:37.915Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
2019-03-21T01:25:37.918Z azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
    at writeAfterEnd (_stream_writable.js:243:12)
    at TLSSocket.Writable.write (_stream_writable.js:291:5)
    at Transport.write (c:\workspace\perf\t0\node_modules\rhea\lib\transport.js:55:16)
    at SaslClient.write (c:\workspace\perf\t0\node_modules\rhea\lib\sasl.js:291:26)
    at Connection.output (c:\workspace\perf\t0\node_modules\rhea\lib\connection.js:449:28)
    at Connection._write_frame (c:\workspace\perf\t0\node_modules\rhea\lib\connection.js:678:10)
    at Session.output (c:\workspace\perf\t0\node_modules\rhea\lib\session.js:456:21)
    at Sender.link._process (c:\workspace\perf\t0\node_modules\rhea\lib\link.js:121:26)
    at Session._process (c:\workspace\perf\t0\node_modules\rhea\lib\session.js:611:27)
    at Connection._process (c:\workspace\perf\t0\node_modules\rhea\lib\connection.js:668:39)
2019-03-21T01:25:37.918Z azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1776 }
2019-03-21T01:25:37.918Z azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect.
2019-03-21T01:25:37.919Z rhea:frames [connection-1]:1413 -> attach#12 {"name":"t1-queue-keep-open-2-bd1e051a-5787-2b47-900d-7b4169799a6c","source":[],"target":["t1-queue-keep-open-2"]} 
2019-03-21T01:25:37.919Z rhea:raw [connection-1] SENT: 124 0000007c02000585005312d00000006c0000000aa13974312d71756575652d6b6565702d6f70656e2d322d62643165303531612d353738372d326234372d393030642d3762343136393739396136634342404000532845005329d00000001a00000001a11474312d71756575652d6b6565702d6f70656e2d32404043
2019-03-21T01:25:37.925Z rhea:io [connection-1] read 27 bytes
2019-03-21T01:25:37.925Z rhea:io [connection-1] got frame of size 27
2019-03-21T01:25:37.925Z rhea:raw [connection-1] RECV: 27 0000001b02000000005315c00e064170000023cc40410053244540
2019-03-21T01:25:37.925Z rhea:frames [connection-1]:0 <- disposition#15 {"role":true,"first":9164,"settled":true,"state":[]} 
2019-03-21T01:25:37.925Z rhea:events [connection-1] Received disposition for outgoing transfers
2019-03-21T01:25:37.925Z rhea:events [connection-1] Link got event: accepted
2019-03-21T01:25:37.925Z rhea-promise:sender [connection-1] sender got event: 'accepted'. Re-emitting the translated context.
2019-03-21T01:25:37.925Z rhea-promise:translate [connection-1] Translating the context for event: 'accepted'.
2019-03-21T01:25:37.925Z rhea:events [connection-1] Link got event: settled
2019-03-21T01:25:37.925Z rhea-promise:sender [connection-1] sender got event: 'settled'. Re-emitting the translated context.
2019-03-21T01:25:37.925Z rhea-promise:translate [connection-1] Translating the context for event: 'settled'.
2019-03-21T01:25:37.936Z rhea:io [connection-1] read 145 bytes
2019-03-21T01:25:37.936Z rhea:io [connection-1] got frame of size 145
2019-03-21T01:25:37.936Z rhea:raw [connection-1] RECV: 145 0000009102000000005314c0160b520170000023cca004cd2300004340424040404042005373c0330d4040404040a12438396534323362342d643363322d306434372d626137322d63643332663231633931386440404040404040005374c13104a10b7374617475732d636f646571000000caa1127374617475732d6465736372697074696f6ea1084163636570746564
2019-03-21T01:25:37.936Z rhea:frames [connection-1]:0 <- transfer#14 {"handle":1,"delivery_id":9164,"delivery_tag":{"type":"Buffer","data":[205,35,0,0]}} <Buffer 00 53 73 c0 33 0d 40 40 40 40 40 a1 24 38 39 65 34 32 33 62 34 2d 64 33 63 32 2d 30 64 34 37 2d 62 61 37 32 2d 63 64 33 32 66 32 31 63 39 31 38 64 40 ... >
2019-03-21T01:25:37.936Z rhea:events [connection-1] Connection got event: error
2019-03-21T01:25:37.936Z rhea-promise:connection [connection-1] connection got event: 'error'. Re-emitting the translated context.
2019-03-21T01:25:37.936Z rhea-promise:translate [] Translating the context for event: 'error'.
Error [ERR_UNHANDLED_ERROR]: Unhandled error. ([object Object])
    at Connection.emit (events.js:171:17)
    at Connection.EventEmitter.emit (domain.js:441:20)
    at emit (c:\workspace\perf\t0\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (c:\workspace\perf\t0\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Connection._connection.on (c:\workspace\perf\t0\node_modules\rhea-promise\lib\connection.ts:506:9)
    at Connection.emit (events.js:182:13)
    at Connection.EventEmitter.emit (domain.js:441:20)
    at Connection.dispatch (c:\workspace\perf\t0\node_modules\rhea\lib\connection.js:232:37)
    at Connection.input (c:\workspace\perf\t0\node_modules\rhea\lib\connection.js:508:18)
    at TLSSocket.emit (events.js:182:13)

To Reproduce
Steps to reproduce the behavior:

1. Run sample for 5000 clients.

Expected behavior
The test should have continued running exceeding count 1775 without any failures.

[ramya-rao-a]

Closing this issue as the latest version of the @azure/service-bus package has improvements around connection reliability, especially to cater to the write after end error reported in this issue.

We will have a separate stress testing effort across all the 4 languages soon, where we will re-test the above scenario