Event hub client - Unauthorized access after ECONNRESET #174

MatejSkrbis · 2018-11-29T09:58:26Z

After running event hub client for some days locally (with almost no load) I received UnauthorizedError on every partition I was listening to. After that event, client stopped listening and no further messages were received.

Package-name: azure-event-hubs
Package-version: 1.0.7
node.js version: 8.9.4
OS name: Windows 10

I had debug set to
azure:event-hubs:error,azure-amqp-common:error,rhea-promise:error,rhea:events,rhea:frames,rhea:io,rhea:flow

This is part of the output just before Unauthorized access was thrown.

2018-11-28T20:41:49.174Z azure:event-hubs:error [connection-1] Trying to create receiver '29f78f39-5bec-4d76-a3bb-b63d257a35cb' with options { name: '29f78f39-5bec-4d76-a3bb-b63d257a35cb',
  autoaccept: true,
  source: 
   { address: '***/ConsumerGroups/consumers/Partitions/17',
     filter: { 'apache.org:selector-filter:string': [Object] } },
  credit_window: 1000,
  onMessage: [Function],
  onError: [Function],
  onClose: [Function],
  onSessionError: [Function],
  onSessionClose: [Function] }
2018-11-28T20:41:49.175Z rhea:frames [connection-1]:54 -> begin#11 {"incoming_window":2048,"outgoing_window":4294967295} 
2018-11-28T20:41:49.553Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:41:49.553Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:41:49.553Z rhea:frames [connection-1]:56 <- begin#11 {"remote_channel":54,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:41:49.553Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:41:49.555Z rhea:frames [connection-1]:54 -> attach#12 {"name":"29f78f39-5bec-4d76-a3bb-b63d257a35cb","role":true,"source":["***/ConsumerGroups/consumers/Partitions/17",null,null,null,null,null,null,["apache.org:selector-filter:string","amqp.annotation.x-opt-enqueued-time > '1543398960334'"]],"target":[]} 
2018-11-28T20:41:56.790Z rhea:events [connection-1] Connection got event: disconnected
2018-11-28T20:41:56.791Z azure:event-hubs:error [connection-1] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
    at _errnoException (util.js:1022:11)
    at TLSWrap.onread (net.js:615:25) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
2018-11-28T20:41:56.791Z azure:event-hubs:error [connection-1] state: { wasConnectionCloseCalled: false,
  numSenders: 0,
  numReceivers: 58 }
2018-11-28T20:41:56.791Z azure:event-hubs:error [connection-1] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-11-28T20:41:57.092Z azure:event-hubs:error [connection-1] calling detached on receiver '656c5642-c480-4ae8-9e7d-6a4834b0a247' with address '***/ConsumerGroups/$default/Partitions/0'.
2018-11-28T20:41:57.094Z rhea-promise:error [connection-1] The receiver is open ? -> false


...


2018-11-28T20:41:57.143Z azure:event-hubs:error [connection-1] Something is busted. State of Receiver '656c5642-c480-4ae8-9e7d-6a4834b0a247' with address '***/ConsumerGroups/$default/Partitions/0' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver: 
   Receiver {
     domain: null,
     _events: 
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session: 
      Session {
        domain: null,
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Object],
        _session: [Object] },
     _link: 
      Receiver {
        session: [Object],
        connection: [Object],
        name: '656c5642-c480-4ae8-9e7d-6a4834b0a247',
        options: [Object],
        state: [Object],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 0,
        credit: 1000,
        observers: [Object],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions: 
      { name: '656c5642-c480-4ae8-9e7d-6a4834b0a247',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }


...


2018-11-28T20:42:24.722Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.723Z rhea:frames [connection-1]:53 <- begin#11 {"remote_channel":53,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.723Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.723Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.723Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.723Z rhea:frames [connection-1]:54 <- begin#11 {"remote_channel":54,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.723Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.724Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.724Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.724Z rhea:frames [connection-1]:55 <- begin#11 {"remote_channel":57,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.724Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.724Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.724Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.725Z rhea:frames [connection-1]:56 <- begin#11 {"remote_channel":58,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.725Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.725Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.725Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.725Z rhea:frames [connection-1]:57 <- begin#11 {"remote_channel":59,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.725Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.726Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.726Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.726Z rhea:frames [connection-1]:58 <- begin#11 {"remote_channel":60,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.726Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.726Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.727Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.727Z rhea:frames [connection-1]:59 <- begin#11 {"remote_channel":62,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.727Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.727Z rhea:io [connection-1] read 34 bytes
2018-11-28T20:42:24.728Z rhea:io [connection-1] got frame of size 34
2018-11-28T20:42:24.728Z rhea:frames [connection-1]:60 <- begin#11 {"remote_channel":55,"next_outgoing_id":1,"incoming_window":5000,"outgoing_window":2048,"handle_max":255} 
2018-11-28T20:42:24.728Z rhea:events [connection-1] Session got event: session_open
2018-11-28T20:42:24.729Z rhea:frames [connection-1]:55 -> attach#12 {"name":"4e0dd1b4-2dbd-ca4e-a89b-103308c39343","source":[],"target":["$cbs"]} 
2018-11-28T20:42:24.730Z rhea:io [connection-1] read 65 bytes
2018-11-28T20:42:24.730Z rhea:io [connection-1] got frame of size 65
2018-11-28T20:42:24.730Z rhea:frames [connection-1]:2 <- attach#12 {"name":"656c5642-c480-4ae8-9e7d-6a4834b0a247","source":null,"target":null} 
2018-11-28T20:42:24.731Z rhea:events [connection-1] Link got event: receiver_open
2018-11-28T20:42:24.731Z rhea:frames [connection-1]:2 -> flow#13 {"incoming_window":2048,"outgoing_window":4294967295,"link_credit":1000} 
2018-11-28T20:42:24.732Z rhea:io [connection-1] read 15174 bytes
2018-11-28T20:42:24.732Z rhea:io [connection-1] got frame of size 346
2018-11-28T20:42:24.732Z rhea:frames [connection-1]:2 <- detach#16 {"closed":true,"error":{"condition":"amqp:unauthorized-access","description":"Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://***.servicebus.windows.net/***/consumergroups/$default/partitions/0'. TrackingId:273581ec9dec4a34808550fb26dee9d2_G28, SystemTracker:gateway5, Timestamp:2018-11-28T20:42:24"}} 
2018-11-28T20:42:24.732Z rhea:events [connection-1] Link got event: receiver_error
2018-11-28T20:42:24.733Z azure:event-hubs:error [connection-1] An error occurred for Receiver '656c5642-c480-4ae8-9e7d-6a4834b0a247': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://***.servicebus.windows.net/***/consumergroups/$default/partitions/0'. TrackingId:273581ec9dec4a34808550fb26dee9d2_G28, SystemTracker:gateway5, Timestamp:2018-11-28T20:42:24
    at Object.translate (..\node_modules\@azure\amqp-common\lib\errors.ts:522:13)
    at Receiver.EventHubReceiver._onAmqpError (..\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (..\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (..\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (..\node_modules\rhea-promise\lib\link.ts:291:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (..\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2018-11-28T20:42:24.733Z azure:event-hubs:error [connection-1] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.

null: MessagingError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://***.servicebus.windows.net/***/consumergroups/$default/partitions/0'. TrackingId:273581ec9dec4a34808550fb26dee9d2_G28, SystemTracker:gateway5, Timestamp:2018-11-28T20:42:24
condition: "amqp:unauthorized-access"
info: null
message: "Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://***.servicebus.windows.net/***/consumergroups/$default/partitions/0'. TrackingId:273581ec9dec4a34808550fb26dee9d2_G28, SystemTracker:gateway5, Timestamp:2018-11-28T20:42:24"
name: "UnauthorizedError"
retryable: false
stack: "UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://***.servicebus.windows.net/***/consumergroups/$default/partitions/0'. TrackingId:273581ec9dec4a34808550fb26dee9d2_G28, SystemTracker:gateway5, Timestamp:2018-11-28T20:42:24
    at Object.translate (..\node_modules\@azure\amqp-common\lib\errors.ts:522:13)
    at Receiver.EventHubReceiver._onAmqpError (..\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (..\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (..\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (..\node_modules\rhea-promise\lib\link.ts:291:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (c..\node_modules\rhea\lib\link.js:59:37)"
translated: true

The text was updated successfully, but these errors were encountered:

AlexGhiondea · 2018-12-04T18:32:20Z

@MatejSkrbis do you happen to have a small repro for this?

MatejSkrbis · 2018-12-05T11:15:31Z

This error is happening every so often. It wasn't the first time it showed. I cannot reliably reproduce it as it usually takes quite some time before it manifests. I'm also not sure what triggers it.

imalao · 2018-12-11T20:01:18Z

I have been trying to debug the same error. It has occurred consistently after my server has been running for a while, approximately ~7 days, and then the event hub client does not reconnect and receive further messages.

Package-name: azure-event-hubs
Package-version: 1.0.3
node.js version: 9.4.0
OS: Debian GNU/Linux 8

Debug set to azure*,rhea*,-rhea:raw,-rhea:message,-azure:amqp-common:datatransformer

2018-12-11T00:22:41.790Z rhea-promise:connection [connection-2] connection got event: 'disconnected'. Re-emitting the translated context.
2018-12-11T00:22:41.790Z rhea-promise:translate [connection-2] Translating the context for event: 'disconnected'.
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
    at TLSWrap.onread (net.js:660:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] state: { wasConnectionCloseCalled: false,
  numSenders: 0,
  numReceivers: 2 }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-12-11T00:22:42.092Z azure:event-hubs:error [connection-2] calling detached on receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The receiver is open ? -> false
2018-12-11T00:22:42.093Z azure:event-hubs:error [connection-2] calling detached on receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The receiver is open ? -> false
2018-12-11T00:22:42.093Z rhea-promise:receiver [connection-2] receiver has been closed, now closing it's session.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The session is open ? -> false
2018-12-11T00:22:42.093Z rhea-promise:receiver [connection-2] receiver has been closed, now closing it's session.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The session is open ? -> false
2018-12-11T00:22:42.093Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' closed.
2018-12-11T00:22:42.093Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' closed.
2018-12-11T00:22:42.095Z azure:event-hubs:error [connection-2] Something is busted. State of Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver:
   Receiver {
     _events:
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session:
      Session {
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Connection],
        _session: [Session] },
     _link:
      Receiver {
        session: [Session],
        connection: [Connection],
        name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
        options: [Object],
        state: [EndpointState],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 494,
        credit: 756,
        observers: [EventEmitter],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions:
      { name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }
2018-12-11T00:22:42.097Z azure:event-hubs:error [connection-2] Something is busted. State of Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver:
   Receiver {
     _events:
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session:
      Session {
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Connection],
        _session: [Session] },
     _link:
      Receiver {
        session: [Session],
        connection: [Connection],
        name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        options: [Object],
        state: [EndpointState],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 0,
        credit: 1000,
        observers: [EventEmitter],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions:
      { name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }
...

2018-12-11T00:37:51.172Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-11T00:37:51.173Z azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection.
2018-12-11T00:37:51.173Z rhea-promise:connection [connection-2] Trying to create a new amqp connection.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] connection got event: 'connection_open'. Re-emitting the translated context.
2018-12-11T00:37:51.781Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
2018-12-11T00:37:51.781Z azure:event-hubs:connectionContext [connection-2] setting 'wasConnectionCloseCalled' property of connection context to false.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] Resolving the promise with amqp connection.
2018-12-11T00:37:51.781Z azure:amqp-common:cbs [connection-2] Creating sender/receiver links on a session for $cbs endpoint.
2018-12-11T00:37:51.782Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-11T00:37:51.782Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-11T00:37:51.783Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.784Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.784Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.785Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.785Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.785Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.787Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.787Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.847Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_error'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_error'.
2018-12-11T00:37:51.944Z azure:event-hubs:error [connection-2] An error occurred for Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/1'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at Receiver.EventHubReceiver._onAmqpError (/app/node_modules/@azure/event-hubs/dist/lib/eventHubReceiver.js:78:47)
    at Receiver.emit (events.js:182:13)
    at emit (/app/node_modules/rhea-promise/dist/lib/util/utils.js:129:24)
    at Object.emitEvent (/app/node_modules/rhea-promise/dist/lib/util/utils.js:140:9)
    at Receiver._link.on (/app/node_modules/rhea-promise/dist/lib/link.js:248:25)
    at Receiver.emit (events.js:182:13)
    at Receiver.link.dispatch (/app/node_modules/rhea/lib/link.js:59:37)
    at Receiver.link.on_detach (/app/node_modules/rhea/lib/link.js:159:32)
    at Session.on_detach (/app/node_modules/rhea/lib/session.js:714:27)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2018-12-11T00:37:51.944Z azure:event-hubs:error [connection-2] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.
Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/1'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
2018-12-11T00:37:51.944Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_close'. Re-emitting the translated context.
2018-12-11T00:37:51.944Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_close'.
2018-12-11T00:37:51.945Z azure:event-hubs:error [connection-2] 'receiver_close' event occurred for receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'. The associated error is: c {
  value:
   [ Typed { type: [TypeDesc], value: 'amqp:unauthorized-access' },
     Typed {
       type: [TypeDesc],
       value:
        'Unauthorized access. \'Listen\' claim(s) are required to perform this operation. Resource: \'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/1\'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51' },
     Typed { type: [TypeDesc], value: null } ] }
2018-12-11T00:37:51.945Z azure:event-hubs:error [connection-2] 'receiver_close' event occurred on the receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' and the sdk did not initiate this. The receiver is not reconnecting. Hence, calling detached from the _onAmqpClose() handler.
2018-12-11T00:37:51.945Z rhea-promise:error [connection-2] The receiver is open ? -> false
2018-12-11T00:37:51.945Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_error'. Re-emitting the translated context.
2018-12-11T00:37:51.946Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_error'.
2018-12-11T00:37:51.946Z azure:event-hubs:error [connection-2] An error occurred for Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/0'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at Receiver.EventHubReceiver._onAmqpError (/app/node_modules/@azure/event-hubs/dist/lib/eventHubReceiver.js:78:47)
    at Receiver.emit (events.js:182:13)
    at emit (/app/node_modules/rhea-promise/dist/lib/util/utils.js:129:24)
    at Object.emitEvent (/app/node_modules/rhea-promise/dist/lib/util/utils.js:140:9)
    at Receiver._link.on (/app/node_modules/rhea-promise/dist/lib/link.js:248:25)
    at Receiver.emit (events.js:182:13)
    at Receiver.link.dispatch (/app/node_modules/rhea/lib/link.js:59:37)
    at Receiver.link.on_detach (/app/node_modules/rhea/lib/link.js:159:32)
    at Session.on_detach (/app/node_modules/rhea/lib/session.js:714:27)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2018-12-11T00:37:51.946Z azure:event-hubs:error [connection-2] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.
2018-12-11T00:37:51.946Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_close'. Re-emitting the translated context.
2018-12-11T00:37:51.946Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_close'.
Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/0'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
2018-12-11T00:37:51.946Z azure:event-hubs:error [connection-2] 'receiver_close' event occurred for receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'. The associated error is: c {
  value:
   [ Typed { type: [TypeDesc], value: 'amqp:unauthorized-access' },
     Typed {
       type: [TypeDesc],
       value:
        'Unauthorized access. \'Listen\' claim(s) are required to perform this operation. Resource: \'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/0\'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51' },
     Typed { type: [TypeDesc], value: null } ] }```

ramya-rao-a · 2018-12-13T01:13:56Z

Looks like the receiver whose link happens to be closed attempts to do something which results in the "UnauthorizedError"

From the logs provided by both @MatejSkrbis and @imalao, I see the below sequence of events

A connection error with code ECONNRESET occurs
The SDK reacts to this by trying to reconnect any senders/receivers that are in the cache
The line "Something is busted." in the logs tell us that we were trying to re-connect a receiver whose link was closed previously.

Since this closed receiver is not cleared from the cache, I believe some further action on it causes the "UnauthorizedError".

It would help to see how the receiver ended up in the closed state but not removed from the cache.

@imalao Can you provide logs before the "ECONNRESET" error is thrown? That might help in seeing how the receiver ended up in the closed state but not removed from the cache.

If you can provide the logs for a minute before the "UnauthorizedError" error is thrown, then that might help in seeing which action resulted in that error on the receiver.

cc @amarzavery

imalao · 2018-12-13T15:59:24Z

@ramya-rao-a

Here are the full logs from when my program starts to when the "ECONNRESET" error is thrown:

2018-12-10T20:52:48.294Z azure:event-hubs:connectionContext [connection-1] Created connection context successfully.
2018-12-10T20:52:48.294Z azure:event-hubs:iothubClient Getting the hub runtime info from the iothub connection string to get the redirect error.
2018-12-10T20:52:48.295Z azure:event-hubs:management [connection-1] Acquiring lock to get the management req res link.
2018-12-10T20:52:48.296Z azure:event-hubs:linkEntity [connection-1] Acquiring cbs lock: 'negotiateCbs-6dc42146-71b3-744b-991c-44b5f1f8f91a' for creating the cbs session while creating the ManagementClient: 'b5f1eb6f-504d-4352-9b9f-edbb1cf6249b' with address: '/messages/events/$management'.
2018-12-10T20:52:48.296Z azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection.
2018-12-10T20:52:48.297Z rhea-promise:connection [connection-1] Trying to create a new amqp connection.
2018-12-10T20:52:48.836Z rhea-promise:connection [connection-1] connection got event: 'connection_open'. Re-emitting the translated context.
2018-12-10T20:52:48.836Z rhea-promise:translate [connection-1] Translating the context for event: 'connection_open'.
2018-12-10T20:52:48.836Z azure:event-hubs:connectionContext [connection-1] setting 'wasConnectionCloseCalled' property of connection context to false.
2018-12-10T20:52:48.836Z rhea-promise:connection [connection-1] Resolving the promise with amqp connection.
2018-12-10T20:52:48.837Z azure:amqp-common:cbs [connection-1] Creating sender/receiver links on a session for $cbs endpoint.
2018-12-10T20:52:48.838Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:48.839Z rhea-promise:session [connection-1] Calling amqp session.begin().
2018-12-10T20:52:48.904Z rhea-promise:session [connection-1] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:48.904Z rhea-promise:translate [connection-1] Translating the context for event: 'session_open'.
2018-12-10T20:52:48.904Z rhea-promise:session [connection-1] Resolving the promise with amqp session.
2018-12-10T20:52:48.905Z rhea-promise:eventhandler [connection-1] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-10T20:52:48.906Z rhea-promise:eventhandler [connection-1] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-10T20:52:48.971Z rhea-promise:sender [connection-1] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-10T20:52:48.971Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_open'.
2018-12-10T20:52:48.972Z rhea-promise:sender [connection-1] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-10T20:52:48.972Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_flow'.
2018-12-10T20:52:48.972Z rhea-promise:sender [connection-1] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-10T20:52:48.973Z rhea-promise:translate [connection-1] Translating the context for event: 'sendable'.
2018-12-10T20:52:48.973Z rhea-promise:sender [connection-1] Resolving the promise with amqp sender 'db754970-2d65-734c-a165-7e49005574f0'.
2018-12-10T20:52:48.973Z rhea-promise:session [connection-1] Added event handler for event 'session_error' on rhea-promise 'session', while creating the 'receiver'.
2018-12-10T20:52:48.974Z rhea-promise:eventhandler [connection-1] rhea-promise 'receiver' object is listening for events: [ 'message', 'receiver_open', 'receiver_drained', 'receiver_flow', 'receiver_error', 'receiver_close', 'settled' ] emitted by rhea's 'receiver' object.
2018-12-10T20:52:48.974Z rhea-promise:eventhandler [connection-1] ListenerCount for event 'receiver_error' on rhea's 'receiver' object is: 1.
2018-12-10T20:52:49.040Z rhea-promise:receiver [connection-1] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-10T20:52:49.040Z rhea-promise:translate [connection-1] Translating the context for event: 'receiver_open'.
2018-12-10T20:52:49.040Z rhea-promise:receiver [connection-1] Resolving the promise with amqp receiver 'cbs-53357b8e-379c-9b47-9f17-73d5a95b50fe'.
2018-12-10T20:52:49.040Z azure:amqp-common:reqreslink [connection-1] Successfully created the sender and receiver links on the same session.
2018-12-10T20:52:49.041Z azure:amqp-common:cbs [connection-1] Successfully created the cbs sender 'db754970-2d65-734c-a165-7e49005574f0' and receiver 'cbs-53357b8e-379c-9b47-9f17-73d5a95b50fe' links over cbs session.
2018-12-10T20:52:49.044Z azure:event-hubs:linkEntity [connection-1] ManagementClient: calling negotiateClaim for audience 'sb://pf-test-hub.azure-devices.net/messages/events/$management'.
2018-12-10T20:52:49.044Z azure:event-hubs:linkEntity [connection-1] Acquiring cbs lock: 'negotiateClaim-5f2ca978-6167-0840-8286-c872f8bc3e13' for cbs auth for ManagementClient: 'b5f1eb6f-504d-4352-9b9f-edbb1cf6249b' with address '/messages/events/$management'.
2018-12-10T20:52:49.045Z azure:amqp-common:retry [connection-1] Retry for 'cbsAuth', attempt number: 1
2018-12-10T20:52:49.046Z azure:amqp-common:reqreslink [connection-1] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '5aa0b003-4116-4841-b7b3-3d56eff553f5',
  reply_to: 'cbs-53357b8e-379c-9b47-9f17-73d5a95b50fe',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://pf-test-hub.azure-devices.net/messages/events/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T20:52:49.210Z rhea-promise:sender [connection-1] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T20:52:49.210Z rhea-promise:translate [connection-1] Translating the context for event: 'accepted'.
2018-12-10T20:52:49.210Z rhea-promise:sender [connection-1] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T20:52:49.210Z rhea-promise:translate [connection-1] Translating the context for event: 'settled'.
2018-12-10T20:52:49.212Z rhea-promise:receiver [connection-1] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:52:49.212Z rhea-promise:translate [connection-1] Translating the context for event: 'message'.
2018-12-10T20:52:49.213Z azure:amqp-common:reqreslink [connection-1] $cbs response:  {"correlation_id":"5aa0b003-4116-4841-b7b3-3d56eff553f5","application_properties":{"status-code":200,"status-description":"OK"}}
2018-12-10T20:52:49.213Z azure:amqp-common:reqreslink [connection-1] request-messageId | '5aa0b003-4116-4841-b7b3-3d56eff553f5' == '5aa0b003-4116-4841-b7b3-3d56eff553f5' | response-correlationId.
(node:23) [DEP0079] DeprecationWarning: Custom inspection function on Objects via .inspect() is deprecated
2018-12-10T20:52:49.214Z azure:amqp-common:retry [connection-1] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T20:52:49.225Z azure:amqp-common:retry [connection-1] Success result for 'cbsAuth': {"correlation_id":"5aa0b003-4116-4841-b7b3-3d56eff553f5","application_properties":{"status-code":200,"status-description":"OK"}}
2018-12-10T20:52:49.226Z azure:amqp-common:cbs [connection-1] The CBS response is: {"correlation_id":"5aa0b003-4116-4841-b7b3-3d56eff553f5","application_properties":{"status-code":200,"status-description":"OK"}}
2018-12-10T20:52:49.226Z azure:amqp-common:cbs [connection-1] The deserialized CBS response is: { correlationId: '5aa0b003-4116-4841-b7b3-3d56eff553f5', statusCode: 200, satusDescription: 'OK' }
2018-12-10T20:52:49.226Z azure:event-hubs:linkEntity [connection-1] Negotiated claim for ManagementClient 'b5f1eb6f-504d-4352-9b9f-edbb1cf6249b' with with address: /messages/events/$management
2018-12-10T20:52:49.227Z azure:event-hubs:management [connection-1] Creating sender/receiver links on a session for $management endpoint with srOpts: { target: { address: '/messages/events/$management' } }, receiverOpts: { source: { address: '/messages/events/$management' },
  name: 'a11c79f2-098f-4415-a6a2-47c309283f8b',
  target: { address: 'a11c79f2-098f-4415-a6a2-47c309283f8b' },
  onSessionError: [Function: onSessionError] }.
2018-12-10T20:52:49.227Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:49.228Z rhea-promise:session [connection-1] Calling amqp session.begin().
2018-12-10T20:52:49.381Z rhea-promise:session [connection-1] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:49.381Z rhea-promise:translate [connection-1] Translating the context for event: 'session_open'.
2018-12-10T20:52:49.381Z rhea-promise:session [connection-1] Resolving the promise with amqp session.
2018-12-10T20:52:49.382Z rhea-promise:eventhandler [connection-1] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-10T20:52:49.382Z rhea-promise:eventhandler [connection-1] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-10T20:52:49.448Z rhea-promise:sender [connection-1] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-10T20:52:49.448Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_open'.
2018-12-10T20:52:49.448Z rhea-promise:sender [connection-1] sender got event: 'sender_error'. Will re-emit in the next tick, since this happened before the promise for create/close was resolved.
2018-12-10T20:52:49.448Z rhea-promise:sender [connection-1] sender got event: 'sender_close'. Re-emitting the translated context.
2018-12-10T20:52:49.449Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_close'.
2018-12-10T20:52:49.449Z rhea-promise:error [connection-1] Error occurred while creating a sender over amqp connection: c {
  value:
   [ Typed { type: [TypeDesc], value: 'amqp:link:redirect' },
     Typed { type: [TypeDesc], value: null },
     Typed { type: [TypeDesc], value: [Array] } ] }.
2018-12-10T20:52:49.451Z azure:event-hubs:error [connection-1] An error occured while establishing the $management links: { LinkRedirectError: null
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at ManagementClient.<anonymous> (/app/node_modules/@azure/event-hubs/dist/lib/managementClient.js:159:37)
    at Generator.throw (<anonymous>)
    at rejected (/app/node_modules/tslib/tslib.js:105:69)
    at process._tickCallback (internal/process/next_tick.js:68:7)
  name: 'LinkRedirectError',
  translated: true,
  retryable: false,
  info:
   { hostname: 'ihsuprodblres076dednamespace.servicebus.windows.net',
     'network-host': 'ihsuprodblres076dednamespace.servicebus.windows.net',
     port: 5671,
     address:
      'amqps://ihsuprodblres076dednamespace.servicebus.windows.net:5671/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management' },
  condition: 'amqp:link:redirect' }
2018-12-10T20:52:49.451Z azure:event-hubs:error An error occurred while making the request to $management endpoint: { LinkRedirectError: null
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at ManagementClient.<anonymous> (/app/node_modules/@azure/event-hubs/dist/lib/managementClient.js:159:37)
    at Generator.throw (<anonymous>)
    at rejected (/app/node_modules/tslib/tslib.js:105:69)
    at process._tickCallback (internal/process/next_tick.js:68:7)
  name: 'LinkRedirectError',
  translated: true,
  retryable: false,
  info:
   { hostname: 'ihsuprodblres076dednamespace.servicebus.windows.net',
     'network-host': 'ihsuprodblres076dednamespace.servicebus.windows.net',
     port: 5671,
     address:
      'amqps://ihsuprodblres076dednamespace.servicebus.windows.net:5671/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management' },
  condition: 'amqp:link:redirect' }
2018-12-10T20:52:49.451Z azure:event-hubs:error IotHubClient received the error: { LinkRedirectError: null
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at ManagementClient.<anonymous> (/app/node_modules/@azure/event-hubs/dist/lib/managementClient.js:159:37)
    at Generator.throw (<anonymous>)
    at rejected (/app/node_modules/tslib/tslib.js:105:69)
    at process._tickCallback (internal/process/next_tick.js:68:7)
  name: 'LinkRedirectError',
  translated: true,
  retryable: false,
  info:
   { hostname: 'ihsuprodblres076dednamespace.servicebus.windows.net',
     'network-host': 'ihsuprodblres076dednamespace.servicebus.windows.net',
     port: 5671,
     address:
      'amqps://ihsuprodblres076dednamespace.servicebus.windows.net:5671/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management' },
  condition: 'amqp:link:redirect' }
2018-12-10T20:52:49.452Z azure:event-hubs:error Parsed info from redirect error is: { endpoint: 'ihsuprodblres076dednamespace.servicebus.windows.net',
  entityPath: 'iothub-ehub-pf-test-hu-1005325-78b76d275b' }
2018-12-10T20:52:49.452Z azure:event-hubs:iothubClient The EventHub ConnectionString is: 'Endpoint=sb://ihsuprodblres076dednamespace.servicebus.windows.net/;xxx'.
2018-12-10T20:52:49.452Z azure:event-hubs:iothubClient Closing the IotHubClient connection...
2018-12-10T20:52:49.453Z rhea-promise:error [connection-1] The sender is open ? -> true
2018-12-10T20:52:49.453Z rhea-promise:sender [connection-1] sender got event: 'sender_error'. Re-emitting the translated context.
2018-12-10T20:52:49.453Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_error'.
2018-12-10T20:52:49.615Z rhea-promise:sender [connection-1] sender got event: 'sender_close'. Re-emitting the translated context.
2018-12-10T20:52:49.615Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_close'.
2018-12-10T20:52:49.616Z rhea-promise:sender [connection-1] Resolving the promise as the amqp sender has been closed.
2018-12-10T20:52:49.616Z rhea-promise:sender [connection-1] sender has been closed, now closing it's session.
2018-12-10T20:52:49.616Z rhea-promise:error [connection-1] The session is open ? -> true
2018-12-10T20:52:49.616Z rhea-promise:session [connection-1] Calling session.close()
2018-12-10T20:52:49.681Z rhea-promise:session [connection-1] session got event: 'session_close'. Re-emitting the translated context.
2018-12-10T20:52:49.681Z rhea-promise:translate [connection-1] Translating the context for event: 'session_close'.
2018-12-10T20:52:49.682Z rhea-promise:session [connection-1] Resolving the promise as the amqp session has been closed.
2018-12-10T20:52:49.682Z rhea-promise:error [connection-1] The receiver is open ? -> false
2018-12-10T20:52:49.682Z rhea-promise:receiver [connection-1] receiver has been closed, now closing it's session.
2018-12-10T20:52:49.682Z rhea-promise:error [connection-1] The session is open ? -> false
2018-12-10T20:52:49.682Z rhea-promise:error [connection-1] The session is open ? -> false
2018-12-10T20:52:49.682Z azure:amqp-common:cbs [connection-1] Successfully closed the cbs session.
2018-12-10T20:52:49.682Z azure:event-hubs:iothubClient IotHub cbs session closed.
2018-12-10T20:52:49.682Z azure:event-hubs:iothubClient IotHub management client closed.
2018-12-10T20:52:49.683Z rhea-promise:error [connection-1] The connection is open ? -> true
2018-12-10T20:52:49.748Z rhea-promise:connection [connection-1] connection got event: 'connection_close'. Re-emitting the translated context.
2018-12-10T20:52:49.748Z rhea-promise:translate [connection-1] Translating the context for event: 'connection_close'.
2018-12-10T20:52:49.748Z rhea-promise:connection [connection-1] Resolving the promise as the connection has been successfully closed.
2018-12-10T20:52:49.749Z azure:event-hubs:iothubClient Closed the amqp connection 'connection-1' on the iothub client.
2018-12-10T20:52:49.750Z rhea-promise:eventhandler [connection-2] rhea-promise 'connection' object is listening for events: [ 'connection_open', 'connection_close', 'connection_error', 'protocol_error', 'error', 'disconnected', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close', 'session_error', 'session_close' ] emitted by rhea's 'connection' object.
2018-12-10T20:52:49.750Z azure:event-hubs:connectionContext [connection-2] Created connection context successfully.
Successully created the EventHub Client from iothub connection string.
2018-12-10T20:52:49.751Z azure:event-hubs:management [connection-2] Acquiring lock to get the management req res link.
2018-12-10T20:52:49.751Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-10T20:52:49.752Z azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection.
2018-12-10T20:52:49.752Z rhea-promise:connection [connection-2] Trying to create a new amqp connection.
2018-12-10T20:52:50.214Z rhea-promise:connection [connection-2] connection got event: 'connection_open'. Re-emitting the translated context.
2018-12-10T20:52:50.214Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
2018-12-10T20:52:50.214Z azure:event-hubs:connectionContext [connection-2] setting 'wasConnectionCloseCalled' property of connection context to false.
2018-12-10T20:52:50.214Z rhea-promise:connection [connection-2] Resolving the promise with amqp connection.
2018-12-10T20:52:50.214Z azure:amqp-common:cbs [connection-2] Creating sender/receiver links on a session for $cbs endpoint.
2018-12-10T20:52:50.215Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:50.215Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-10T20:52:50.279Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:50.279Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-10T20:52:50.280Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-10T20:52:50.280Z rhea-promise:eventhandler [connection-2] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-10T20:52:50.280Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-10T20:52:50.345Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-10T20:52:50.345Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-10T20:52:50.345Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-10T20:52:50.346Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-10T20:52:50.346Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-10T20:52:50.346Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-10T20:52:50.346Z rhea-promise:sender [connection-2] Resolving the promise with amqp sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8'.
2018-12-10T20:52:50.346Z rhea-promise:session [connection-2] Added event handler for event 'session_error' on rhea-promise 'session', while creating the 'receiver'.
2018-12-10T20:52:50.347Z rhea-promise:eventhandler [connection-2] rhea-promise 'receiver' object is listening for events: [ 'message', 'receiver_open', 'receiver_drained', 'receiver_flow', 'receiver_error', 'receiver_close', 'settled' ] emitted by rhea's 'receiver' object.
2018-12-10T20:52:50.347Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'receiver_error' on rhea's 'receiver' object is: 1.
2018-12-10T20:52:50.412Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-10T20:52:50.412Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-10T20:52:50.412Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353'.
2018-12-10T20:52:50.412Z azure:amqp-common:reqreslink [connection-2] Successfully created the sender and receiver links on the same session.
2018-12-10T20:52:50.412Z azure:amqp-common:cbs [connection-2] Successfully created the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T20:52:50.414Z azure:event-hubs:linkEntity [connection-2] ManagementClient: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management'.
2018-12-10T20:52:50.414Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address '$management'.
2018-12-10T20:52:50.415Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T20:52:50.415Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'a983320d-5d59-bc41-9c4c-9a3e9a44302d',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T20:52:50.584Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T20:52:50.584Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T20:52:50.584Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T20:52:50.584Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T20:52:50.584Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:52:50.584Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T20:52:50.584Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"a983320d-5d59-bc41-9c4c-9a3e9a44302d","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:50.585Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'a983320d-5d59-bc41-9c4c-9a3e9a44302d' == 'a983320d-5d59-bc41-9c4c-9a3e9a44302d' | response-correlationId.
2018-12-10T20:52:50.585Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T20:52:50.585Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"a983320d-5d59-bc41-9c4c-9a3e9a44302d","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:50.585Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"a983320d-5d59-bc41-9c4c-9a3e9a44302d","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:50.585Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'a983320d-5d59-bc41-9c4c-9a3e9a44302d', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T20:52:50.585Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with with address: $management
2018-12-10T20:52:50.585Z azure:event-hubs:management [connection-2] Creating sender/receiver links on a session for $management endpoint with srOpts: { target: { address: '$management' } }, receiverOpts: { source: { address: '$management' },
  name: '5e7877f6-ca96-4e63-a25b-06d95cbe4d51',
  target: { address: '5e7877f6-ca96-4e63-a25b-06d95cbe4d51' },
  onSessionError: [Function: onSessionError] }.
2018-12-10T20:52:50.585Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:50.586Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-10T20:52:50.756Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:50.756Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-10T20:52:50.756Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-10T20:52:50.757Z rhea-promise:eventhandler [connection-2] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-10T20:52:50.757Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-10T20:52:50.821Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-10T20:52:50.821Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-10T20:52:50.822Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-10T20:52:50.822Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-10T20:52:50.822Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-10T20:52:50.822Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-10T20:52:50.822Z rhea-promise:sender [connection-2] Resolving the promise with amqp sender '2d1765b9-ab9b-c84f-98d4-46d7f4756b44'.
2018-12-10T20:52:50.822Z rhea-promise:session [connection-2] Added event handler for event 'session_error' on rhea-promise 'session', while creating the 'receiver'.
2018-12-10T20:52:50.822Z rhea-promise:eventhandler [connection-2] rhea-promise 'receiver' object is listening for events: [ 'message', 'receiver_open', 'receiver_drained', 'receiver_flow', 'receiver_error', 'receiver_close', 'settled' ] emitted by rhea's 'receiver' object.
2018-12-10T20:52:50.822Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'receiver_error' on rhea's 'receiver' object is: 1.
2018-12-10T20:52:50.887Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-10T20:52:50.887Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-10T20:52:50.887Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver '5e7877f6-ca96-4e63-a25b-06d95cbe4d51'.
2018-12-10T20:52:50.888Z azure:amqp-common:reqreslink [connection-2] Successfully created the sender and receiver links on the same session.
2018-12-10T20:52:50.888Z azure:event-hubs:management [connection-2] Created sender '2d1765b9-ab9b-c84f-98d4-46d7f4756b44' and receiver '5e7877f6-ca96-4e63-a25b-06d95cbe4d51' links for $management endpoint.
2018-12-10T20:52:50.889Z azure:event-hubs:linkEntity [connection-2] ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with address $management, has next token renewal in 2700 seconds @(Mon Dec 10 2018 21:37:50 GMT+0000 (Coordinated Universal Time)).
2018-12-10T20:52:50.889Z azure:amqp-common:retry [connection-2] Retry for 'management', attempt number: 1
2018-12-10T20:52:50.889Z azure:amqp-common:reqreslink [connection-2] $managment request sent: { body: <Buffer 5b 5d>,
  message_id: '46ace93c-0a6a-4369-9482-96e0d3ea8cee',
  reply_to: '5e7877f6-ca96-4e63-a25b-06d95cbe4d51',
  application_properties:
   { operation: 'READ',
     name: 'iothub-ehub-pf-test-hu-1005325-78b76d275b',
     type: 'com.microsoft:eventhub' } }
2018-12-10T20:52:51.053Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T20:52:51.053Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T20:52:51.053Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T20:52:51.054Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T20:52:51.054Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:52:51.054Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T20:52:51.054Z azure:amqp-common:reqreslink [connection-2] $management response:  {"correlation_id":"46ace93c-0a6a-4369-9482-96e0d3ea8cee","application_properties":{"operation":"READ","status-code":200,"status-description":"OK"},"body":{"name":"iothub-ehub-pf-test-hu-1005325-78b76d275b","type":"com.microsoft:eventhub","created_at":1543332856363,"partition_count":2,"partition_ids":["0","1"]}}
2018-12-10T20:52:51.055Z azure:amqp-common:reqreslink [connection-2] request-messageId | '46ace93c-0a6a-4369-9482-96e0d3ea8cee' == '46ace93c-0a6a-4369-9482-96e0d3ea8cee' | response-correlationId.
2018-12-10T20:52:51.055Z azure:amqp-common:retry [connection-2] Success for 'management', after attempt number: 1.
2018-12-10T20:52:51.055Z azure:amqp-common:retry [connection-2] Success result for 'management': {"correlation_id":"46ace93c-0a6a-4369-9482-96e0d3ea8cee","application_properties":{"operation":"READ","status-code":200,"status-description":"OK"},"body":{"name":"iothub-ehub-pf-test-hu-1005325-78b76d275b","type":"com.microsoft:eventhub","created_at":1543332856363,"partition_count":2,"partition_ids":["0","1"]}}
2018-12-10T20:52:51.055Z azure:event-hubs:management [connection-2] The hub runtime info is: { path: 'iothub-ehub-pf-test-hu-1005325-78b76d275b',
  createdAt: 2018-11-27T15:34:16.363Z,
  partitionCount: 2,
  partitionIds: [ '0', '1' ],
  type: 'com.microsoft:eventhub' }
The partition ids are:  [ '0', '1' ]
2018-12-10T20:52:51.056Z azure:event-hubs:error [connection-2] Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' is open? -> undefined
2018-12-10T20:52:51.056Z azure:event-hubs:error [connection-2] Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' is open? -> undefined
2018-12-10T20:52:51.057Z azure:event-hubs:error [connection-2] The receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' is not open and is not currently establishing itself. Hence let's try to connect.
2018-12-10T20:52:51.057Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T20:52:51.057Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T20:52:51.057Z azure:event-hubs:error [connection-2] Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is open? -> undefined
2018-12-10T20:52:51.057Z azure:event-hubs:error [connection-2] Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is open? -> undefined
2018-12-10T20:52:51.057Z azure:event-hubs:error [connection-2] The receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is not open and is not currently establishing itself. Hence let's try to connect.
2018-12-10T20:52:51.057Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T20:52:51.057Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T20:52:51.059Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T20:52:51.059Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T20:52:51.059Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T20:52:51.059Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '7098a783-e058-9e49-889d-1d3f07602200',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T20:52:51.060Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T20:52:51.060Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T20:52:51.225Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T20:52:51.226Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T20:52:51.226Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T20:52:51.226Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T20:52:51.226Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:52:51.226Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T20:52:51.226Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"7098a783-e058-9e49-889d-1d3f07602200","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.226Z azure:amqp-common:reqreslink [connection-2] request-messageId | '7098a783-e058-9e49-889d-1d3f07602200' == '7098a783-e058-9e49-889d-1d3f07602200' | response-correlationId.
2018-12-10T20:52:51.227Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T20:52:51.227Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"7098a783-e058-9e49-889d-1d3f07602200","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.227Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"7098a783-e058-9e49-889d-1d3f07602200","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.227Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '7098a783-e058-9e49-889d-1d3f07602200', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T20:52:51.227Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T20:52:51.227Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '5f3b80db-0681-c747-9a73-eb78c3f3f734',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T20:52:51.228Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0
2018-12-10T20:52:51.228Z azure:event-hubs:error [connection-2] Trying to create receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with options { name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
  autoaccept: true,
  source:
   { address:
      'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     filter: { 'apache.org:selector-filter:string': [Typed] } },
  credit_window: 1000,
  onMessage: [Function],
  onError: [Function],
  onClose: [Function],
  onSessionError: [Function],
  onSessionClose: [Function] }
2018-12-10T20:52:51.229Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:51.229Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-10T20:52:51.397Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:51.397Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-10T20:52:51.397Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-10T20:52:51.397Z rhea-promise:session [connection-2] Added event handler for event 'session_error' on rhea-promise 'session', while creating the 'receiver'.
2018-12-10T20:52:51.397Z rhea-promise:session [connection-2] Added event handler for event 'session_close' on rhea-promise 'session',  while creating the 'receiver'.
2018-12-10T20:52:51.398Z rhea-promise:eventhandler [connection-2] rhea-promise 'receiver' object is listening for events: [ 'message', 'receiver_open', 'receiver_drained', 'receiver_flow', 'receiver_error', 'receiver_close', 'settled' ] emitted by rhea's 'receiver' object.
2018-12-10T20:52:51.398Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'receiver_error' on rhea's 'receiver' object is: 1.
2018-12-10T20:52:51.398Z rhea-promise:receiver [connection-2] Added event handler for event 'message' on rhea-promise 'receiver'.
2018-12-10T20:52:51.398Z rhea-promise:receiver [connection-2] Added event handler for event 'receiver_error' on rhea-promise 'receiver'.
2018-12-10T20:52:51.398Z rhea-promise:receiver [connection-2] Added event handler for event 'receiver_close' on rhea-promise 'receiver'.
2018-12-10T20:52:51.399Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T20:52:51.399Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T20:52:51.399Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T20:52:51.399Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T20:52:51.399Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:52:51.399Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T20:52:51.399Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"5f3b80db-0681-c747-9a73-eb78c3f3f734","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.399Z azure:amqp-common:reqreslink [connection-2] request-messageId | '5f3b80db-0681-c747-9a73-eb78c3f3f734' == '5f3b80db-0681-c747-9a73-eb78c3f3f734' | response-correlationId.
2018-12-10T20:52:51.400Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T20:52:51.400Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"5f3b80db-0681-c747-9a73-eb78c3f3f734","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.400Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"5f3b80db-0681-c747-9a73-eb78c3f3f734","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T20:52:51.400Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '5f3b80db-0681-c747-9a73-eb78c3f3f734', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T20:52:51.400Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T20:52:51.401Z azure:event-hubs:error [connection-2] Trying to create receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with options { name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
  autoaccept: true,
  source:
   { address:
      'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     filter: { 'apache.org:selector-filter:string': [Typed] } },
  credit_window: 1000,
  onMessage: [Function],
  onError: [Function],
  onClose: [Function],
  onSessionError: [Function],
  onSessionClose: [Function] }
2018-12-10T20:52:51.401Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-10T20:52:51.401Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-10T20:52:51.466Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-10T20:52:51.466Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-10T20:52:51.466Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781'.
2018-12-10T20:52:51.466Z azure:event-hubs:error [connection-2] Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' has established itself.
2018-12-10T20:52:51.466Z azure:event-hubs:receiver Promise to create the receiver resolved. Created receiver with name:  d32f0fc0-becb-4189-b572-7b934b5f6781
2018-12-10T20:52:51.467Z azure:event-hubs:receiver [connection-2] Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' created with receiver options: { name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
  autoaccept: true,
  source:
   { address:
      'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     filter: { 'apache.org:selector-filter:string': [Typed] } },
  credit_window: 1000,
  onMessage: [Function],
  onError: [Function],
  onClose: [Function],
  onSessionError: [Function],
  onSessionClose: [Function] }
2018-12-10T20:52:51.467Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0, has next token renewal in 2700 seconds @(Mon Dec 10 2018 21:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T20:52:51.530Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-10T20:52:51.530Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-10T20:52:51.530Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-10T20:52:51.530Z rhea-promise:session [connection-2] Added event handler for event 'session_error' on rhea-promise 'session', while creating the 'receiver'.
2018-12-10T20:52:51.531Z rhea-promise:session [connection-2] Added event handler for event 'session_close' on rhea-promise 'session',  while creating the 'receiver'.
2018-12-10T20:52:51.531Z rhea-promise:eventhandler [connection-2] rhea-promise 'receiver' object is listening for events: [ 'message', 'receiver_open', 'receiver_drained', 'receiver_flow', 'receiver_error', 'receiver_close', 'settled' ] emitted by rhea's 'receiver' object.
2018-12-10T20:52:51.531Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'receiver_error' on rhea's 'receiver' object is: 1.
2018-12-10T20:52:51.531Z rhea-promise:receiver [connection-2] Added event handler for event 'message' on rhea-promise 'receiver'.
2018-12-10T20:52:51.531Z rhea-promise:receiver [connection-2] Added event handler for event 'receiver_error' on rhea-promise 'receiver'.
2018-12-10T20:52:51.531Z rhea-promise:receiver [connection-2] Added event handler for event 'receiver_close' on rhea-promise 'receiver'.
2018-12-10T20:52:51.700Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-10T20:52:51.700Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-10T20:52:51.700Z rhea-promise:receiver [connection-2] Resolving the promise with amqp receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d'.
2018-12-10T20:52:51.700Z azure:event-hubs:error [connection-2] Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' has established itself.
2018-12-10T20:52:51.701Z azure:event-hubs:receiver Promise to create the receiver resolved. Created receiver with name:  9d5cfb5d-df29-49b1-8c3b-a4239077874d
2018-12-10T20:52:51.701Z azure:event-hubs:receiver [connection-2] Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' created with receiver options: { name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
  autoaccept: true,
  source:
   { address:
      'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     filter: { 'apache.org:selector-filter:string': [Typed] } },
  credit_window: 1000,
  onMessage: [Function],
  onError: [Function],
  onClose: [Function],
  onSessionError: [Function],
  onSessionClose: [Function] }
2018-12-10T20:52:51.701Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Mon Dec 10 2018 21:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T20:53:15.255Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T20:53:15.256Z rhea-promise:translate [connection-2] Translating the context for event: 'message'
....

2018-12-10T21:37:48.218Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T21:37:48.218Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T21:37:50.890Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-10T21:37:50.890Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T21:37:50.891Z azure:event-hubs:linkEntity [connection-2] ManagementClient: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management'.
2018-12-10T21:37:50.892Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address '$management'.
2018-12-10T21:37:50.892Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T21:37:50.892Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '4f0c2a57-b74d-6246-8989-71bd2abc42b8',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T21:37:50.958Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T21:37:50.958Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T21:37:50.958Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T21:37:50.958Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T21:37:50.958Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T21:37:50.958Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T21:37:50.959Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"4f0c2a57-b74d-6246-8989-71bd2abc42b8","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:50.959Z azure:amqp-common:reqreslink [connection-2] request-messageId | '4f0c2a57-b74d-6246-8989-71bd2abc42b8' == '4f0c2a57-b74d-6246-8989-71bd2abc42b8' | response-correlationId.
2018-12-10T21:37:50.959Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T21:37:50.959Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"4f0c2a57-b74d-6246-8989-71bd2abc42b8","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:50.959Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"4f0c2a57-b74d-6246-8989-71bd2abc42b8","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:50.959Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '4f0c2a57-b74d-6246-8989-71bd2abc42b8', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T21:37:50.959Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with with address: $management
2018-12-10T21:37:50.959Z azure:event-hubs:linkEntity [connection-2] ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with address $management, has next token renewal in 2700 seconds @(Mon Dec 10 2018 22:22:50 GMT+0000 (Coordinated Universal Time)).
2018-12-10T21:37:51.467Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T21:37:51.467Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T21:37:51.469Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T21:37:51.470Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T21:37:51.470Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T21:37:51.470Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'bfd43c73-b717-4948-8841-99ad45581346',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T21:37:51.536Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T21:37:51.536Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T21:37:51.536Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T21:37:51.536Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T21:37:51.537Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T21:37:51.537Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T21:37:51.537Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"bfd43c73-b717-4948-8841-99ad45581346","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.537Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'bfd43c73-b717-4948-8841-99ad45581346' == 'bfd43c73-b717-4948-8841-99ad45581346' | response-correlationId.
2018-12-10T21:37:51.537Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T21:37:51.537Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"bfd43c73-b717-4948-8841-99ad45581346","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.537Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"bfd43c73-b717-4948-8841-99ad45581346","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.538Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'bfd43c73-b717-4948-8841-99ad45581346', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T21:37:51.538Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0
2018-12-10T21:37:51.538Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0, has next token renewal in 2700 seconds @(Mon Dec 10 2018 22:22:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T21:37:51.701Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T21:37:51.702Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T21:37:51.703Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T21:37:51.703Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T21:37:51.703Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T21:37:51.704Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx,
  message_id: '505d1b6c-e4cb-4245-89df-ac600a36903b',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T21:37:51.771Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T21:37:51.771Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T21:37:51.771Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T21:37:51.771Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T21:37:51.772Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T21:37:51.772Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T21:37:51.772Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"505d1b6c-e4cb-4245-89df-ac600a36903b","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.772Z azure:amqp-common:reqreslink [connection-2] request-messageId | '505d1b6c-e4cb-4245-89df-ac600a36903b' == '505d1b6c-e4cb-4245-89df-ac600a36903b' | response-correlationId.
2018-12-10T21:37:51.772Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T21:37:51.772Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"505d1b6c-e4cb-4245-89df-ac600a36903b","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.773Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"505d1b6c-e4cb-4245-89df-ac600a36903b","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T21:37:51.773Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '505d1b6c-e4cb-4245-89df-ac600a36903b', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T21:37:51.773Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T21:37:51.773Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Mon Dec 10 2018 22:22:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T21:38:16.576Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T21:38:16.576Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.

....

2018-12-10T22:22:44.133Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T22:22:44.133Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T22:22:50.961Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-10T22:22:50.962Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T22:22:50.962Z azure:event-hubs:linkEntity [connection-2] ManagementClient: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management'.
2018-12-10T22:22:50.962Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address '$management'.
2018-12-10T22:22:50.963Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T22:22:50.963Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '7058d550-c59f-c54e-886b-718f56efd5bd',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T22:22:51.028Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T22:22:51.028Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T22:22:51.028Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T22:22:51.028Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T22:22:51.029Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T22:22:51.029Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T22:22:51.029Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"7058d550-c59f-c54e-886b-718f56efd5bd","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.029Z azure:amqp-common:reqreslink [connection-2] request-messageId | '7058d550-c59f-c54e-886b-718f56efd5bd' == '7058d550-c59f-c54e-886b-718f56efd5bd' | response-correlationId.
2018-12-10T22:22:51.029Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T22:22:51.029Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"7058d550-c59f-c54e-886b-718f56efd5bd","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.029Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"7058d550-c59f-c54e-886b-718f56efd5bd","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.029Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '7058d550-c59f-c54e-886b-718f56efd5bd', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T22:22:51.030Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with with address: $management
2018-12-10T22:22:51.030Z azure:event-hubs:linkEntity [connection-2] ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with address $management, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:07:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T22:22:51.538Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T22:22:51.539Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T22:22:51.539Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T22:22:51.539Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T22:22:51.539Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T22:22:51.540Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'e25e8396-459e-584b-994d-44d9f4c06454',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T22:22:51.605Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T22:22:51.605Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T22:22:51.605Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T22:22:51.605Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T22:22:51.605Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T22:22:51.605Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T22:22:51.605Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"e25e8396-459e-584b-994d-44d9f4c06454","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.606Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'e25e8396-459e-584b-994d-44d9f4c06454' == 'e25e8396-459e-584b-994d-44d9f4c06454' | response-correlationId.
2018-12-10T22:22:51.606Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T22:22:51.606Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"e25e8396-459e-584b-994d-44d9f4c06454","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.606Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"e25e8396-459e-584b-994d-44d9f4c06454","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.606Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'e25e8396-459e-584b-994d-44d9f4c06454', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T22:22:51.606Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0
2018-12-10T22:22:51.606Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:07:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T22:22:51.774Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T22:22:51.774Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T22:22:51.774Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T22:22:51.774Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T22:22:51.775Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T22:22:51.775Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'de8cc798-4961-0a4a-a44f-69083f151994',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T22:22:51.840Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T22:22:51.840Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T22:22:51.840Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T22:22:51.840Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T22:22:51.840Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T22:22:51.840Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T22:22:51.840Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"de8cc798-4961-0a4a-a44f-69083f151994","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.840Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'de8cc798-4961-0a4a-a44f-69083f151994' == 'de8cc798-4961-0a4a-a44f-69083f151994' | response-correlationId.
2018-12-10T22:22:51.841Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T22:22:51.841Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"de8cc798-4961-0a4a-a44f-69083f151994","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.841Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"de8cc798-4961-0a4a-a44f-69083f151994","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T22:22:51.841Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'de8cc798-4961-0a4a-a44f-69083f151994', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T22:22:51.841Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T22:22:51.841Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:07:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T22:23:18.157Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T22:23:18.157Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.

....

2018-12-10T23:07:40.237Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:07:40.237Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:07:51.032Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-10T23:07:51.032Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:07:51.033Z azure:event-hubs:linkEntity [connection-2] ManagementClient: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management'.
2018-12-10T23:07:51.033Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address '$management'.
2018-12-10T23:07:51.033Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:07:51.033Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'e0fa4627-0b76-b94b-a405-899ca94548d1',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:07:51.099Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:07:51.099Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:07:51.099Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:07:51.099Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:07:51.099Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:07:51.099Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:07:51.099Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"e0fa4627-0b76-b94b-a405-899ca94548d1","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.099Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'e0fa4627-0b76-b94b-a405-899ca94548d1' == 'e0fa4627-0b76-b94b-a405-899ca94548d1' | response-correlationId.
2018-12-10T23:07:51.100Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:07:51.100Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"e0fa4627-0b76-b94b-a405-899ca94548d1","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.100Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"e0fa4627-0b76-b94b-a405-899ca94548d1","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.100Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'e0fa4627-0b76-b94b-a405-899ca94548d1', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:07:51.100Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with with address: $management
2018-12-10T23:07:51.100Z azure:event-hubs:linkEntity [connection-2] ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with address $management, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:52:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:07:51.607Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:07:51.607Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:07:51.607Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:07:51.607Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:07:51.608Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:07:51.608Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '9fe8db9a-56d5-6946-990f-906e0f14cd45',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:07:51.674Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:07:51.674Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:07:51.674Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:07:51.674Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:07:51.675Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:07:51.675Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:07:51.675Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"9fe8db9a-56d5-6946-990f-906e0f14cd45","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.675Z azure:amqp-common:reqreslink [connection-2] request-messageId | '9fe8db9a-56d5-6946-990f-906e0f14cd45' == '9fe8db9a-56d5-6946-990f-906e0f14cd45' | response-correlationId.
2018-12-10T23:07:51.675Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:07:51.675Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"9fe8db9a-56d5-6946-990f-906e0f14cd45","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.675Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"9fe8db9a-56d5-6946-990f-906e0f14cd45","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.675Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '9fe8db9a-56d5-6946-990f-906e0f14cd45', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:07:51.675Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0
2018-12-10T23:07:51.675Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:52:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:07:51.841Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:07:51.841Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:07:51.842Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:07:51.842Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:07:51.842Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:07:51.842Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'a5f6aa7d-350f-7245-ab1b-b9385f0e0d92',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:07:51.908Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:07:51.908Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:07:51.908Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:07:51.908Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:07:51.908Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:07:51.908Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:07:51.908Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"a5f6aa7d-350f-7245-ab1b-b9385f0e0d92","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.908Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'a5f6aa7d-350f-7245-ab1b-b9385f0e0d92' == 'a5f6aa7d-350f-7245-ab1b-b9385f0e0d92' | response-correlationId.
2018-12-10T23:07:51.909Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:07:51.909Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"a5f6aa7d-350f-7245-ab1b-b9385f0e0d92","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.909Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"a5f6aa7d-350f-7245-ab1b-b9385f0e0d92","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:07:51.909Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'a5f6aa7d-350f-7245-ab1b-b9385f0e0d92', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:07:51.909Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T23:07:51.909Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Mon Dec 10 2018 23:52:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:08:19.972Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:08:19.973Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.

....

2018-12-10T23:52:42.383Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:52:42.384Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:52:51.102Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-10T23:52:51.102Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:52:51.103Z azure:event-hubs:linkEntity [connection-2] ManagementClient: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management'.
2018-12-10T23:52:51.103Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address '$management'.
2018-12-10T23:52:51.103Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:52:51.103Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '60e6a3f1-a35e-a247-8928-cf7ba8b34310',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/$management',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:52:51.169Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:52:51.169Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:52:51.169Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:52:51.170Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:52:51.170Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:52:51.170Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:52:51.170Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"60e6a3f1-a35e-a247-8928-cf7ba8b34310","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.170Z azure:amqp-common:reqreslink [connection-2] request-messageId | '60e6a3f1-a35e-a247-8928-cf7ba8b34310' == '60e6a3f1-a35e-a247-8928-cf7ba8b34310' | response-correlationId.
2018-12-10T23:52:51.170Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:52:51.170Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"60e6a3f1-a35e-a247-8928-cf7ba8b34310","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.171Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"60e6a3f1-a35e-a247-8928-cf7ba8b34310","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.171Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '60e6a3f1-a35e-a247-8928-cf7ba8b34310', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:52:51.171Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with with address: $management
2018-12-10T23:52:51.171Z azure:event-hubs:linkEntity [connection-2] ManagementClient 'de979bba-3b79-460c-97d9-abe99bc20785' with address $management, has next token renewal in 2700 seconds @(Tue Dec 11 2018 00:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:52:51.677Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:52:51.677Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:52:51.678Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:52:51.678Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-10T23:52:51.678Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:52:51.678Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: '325ec4d7-0ef1-f74c-bdf7-af41411c2e9f',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:52:51.744Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:52:51.744Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:52:51.744Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:52:51.744Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:52:51.744Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:52:51.744Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:52:51.744Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"325ec4d7-0ef1-f74c-bdf7-af41411c2e9f","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.744Z azure:amqp-common:reqreslink [connection-2] request-messageId | '325ec4d7-0ef1-f74c-bdf7-af41411c2e9f' == '325ec4d7-0ef1-f74c-bdf7-af41411c2e9f' | response-correlationId.
2018-12-10T23:52:51.745Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:52:51.745Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"325ec4d7-0ef1-f74c-bdf7-af41411c2e9f","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.745Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"325ec4d7-0ef1-f74c-bdf7-af41411c2e9f","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.745Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: '325ec4d7-0ef1-f74c-bdf7-af41411c2e9f', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:52:51.745Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0
2018-12-10T23:52:51.745Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0, has next token renewal in 2700 seconds @(Tue Dec 11 2018 00:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:52:51.909Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address: 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:52:51.910Z azure:amqp-common:cbs [connection-2] CBS session is already present. Reusing the cbs sender '9194327b-125f-ae41-8d4f-b7c9ae17edd8' and receiver 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353' links over cbs session.
2018-12-10T23:52:51.910Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver: calling negotiateClaim for audience 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:52:51.910Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-10T23:52:51.910Z azure:amqp-common:retry [connection-2] Retry for 'cbsAuth', attempt number: 1
2018-12-10T23:52:51.910Z azure:amqp-common:reqreslink [connection-2] $cbs request sent: { body:
   'SharedAccessSignature xxx',
  message_id: 'ae4a2f2f-53ad-6f48-b9e1-5363b00d5893',
  reply_to: 'cbs-1a6b4794-2532-7f4a-86de-7240b240f353',
  to: '$cbs',
  application_properties:
   { operation: 'put-token',
     name:
      'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1',
     type: 'servicebus.windows.net:sastoken' } }
2018-12-10T23:52:51.976Z rhea-promise:sender [connection-2] sender got event: 'accepted'. Re-emitting the translated context.
2018-12-10T23:52:51.976Z rhea-promise:translate [connection-2] Translating the context for event: 'accepted'.
2018-12-10T23:52:51.977Z rhea-promise:sender [connection-2] sender got event: 'settled'. Re-emitting the translated context.
2018-12-10T23:52:51.977Z rhea-promise:translate [connection-2] Translating the context for event: 'settled'.
2018-12-10T23:52:51.983Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:52:51.983Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:52:51.983Z azure:amqp-common:reqreslink [connection-2] $cbs response:  {"correlation_id":"ae4a2f2f-53ad-6f48-b9e1-5363b00d5893","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.983Z azure:amqp-common:reqreslink [connection-2] request-messageId | 'ae4a2f2f-53ad-6f48-b9e1-5363b00d5893' == 'ae4a2f2f-53ad-6f48-b9e1-5363b00d5893' | response-correlationId.
2018-12-10T23:52:51.983Z azure:amqp-common:retry [connection-2] Success for 'cbsAuth', after attempt number: 1.
2018-12-10T23:52:51.983Z azure:amqp-common:retry [connection-2] Success result for 'cbsAuth': {"correlation_id":"ae4a2f2f-53ad-6f48-b9e1-5363b00d5893","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.983Z azure:amqp-common:cbs [connection-2] The CBS response is: {"correlation_id":"ae4a2f2f-53ad-6f48-b9e1-5363b00d5893","application_properties":{"status-code":202,"status-description":"Accepted"}}
2018-12-10T23:52:51.984Z azure:amqp-common:cbs [connection-2] The deserialized CBS response is: { correlationId: 'ae4a2f2f-53ad-6f48-b9e1-5363b00d5893', statusCode: 202, satusDescription: 'Accepted' }
2018-12-10T23:52:51.984Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T23:52:51.984Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Tue Dec 11 2018 00:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:53:21.381Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:53:21.381Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.


....


2018-12-11T00:22:22.522Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:22:22.522Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:22:41.790Z rhea-promise:connection [connection-2] connection got event: 'disconnected'. Re-emitting the translated context.
2018-12-11T00:22:41.790Z rhea-promise:translate [connection-2] Translating the context for event: 'disconnected'.
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
    at TLSWrap.onread (net.js:660:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] state: { wasConnectionCloseCalled: false,
  numSenders: 0,
  numReceivers: 2 }

Thanks for your help.

ramya-rao-a · 2018-12-13T19:05:50Z

Thanks @imalao

These logs show the successful creation and use of the 2 streaming receivers. But, logs for the time just before the ECONNRESET error is missing. This error happens at 00:22:41. Can you share the logs from just before that? I want to see if the 2 receivers were working fine just before the ECONNRESET error.

Also, logs just before the Unauthorized error would also help. The UnauthorizedError in your logs occur at 00:37:51. Was that the first occurrence of this error after 00:22:41? If yes, then can you share the logs for 1 minute duration before this error. If not, then please share the logs for 1 minute duration before the first occurrence of this error after 00:22:41.

If you are more comfortable sharing the logs via email, you can do so as well. If you want to share the entire stretch instead of the various chunks, then we would need the logs from say 00:18 to 00:37.

For protecting your privacy, feel free to redact the lines with the word "SharedAccess"

imalao · 2018-12-13T20:45:22Z

@ramya-rao-a It seems the 2 receivers were working fine just before the ECONNRESET error. Here are the logs:

2018-12-10T23:52:51.984Z azure:event-hubs:linkEntity [connection-2] Negotiated claim for StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with with address: iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1
2018-12-10T23:52:51.984Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1, has next token renewal in 2700 seconds @(Tue Dec 11 2018 00:37:51 GMT+0000 (Coordinated Universal Time)).
2018-12-10T23:53:21.381Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:53:21.381Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:53:21.381Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:53:21.381Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:54:21.447Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:54:21.447Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:54:21.447Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:54:21.447Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:55:21.317Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:55:21.317Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:55:21.318Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:55:21.318Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:56:21.429Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:56:21.429Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:56:21.430Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:56:21.430Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:57:21.514Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:57:21.514Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:57:21.515Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:57:21.515Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:57:36.266Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:57:36.266Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:57:45.296Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:57:45.297Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:58:21.555Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:58:21.555Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:58:21.555Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:58:21.556Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:59:21.545Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:59:21.545Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-10T23:59:21.546Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-10T23:59:21.546Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:00:21.642Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:00:21.642Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:00:21.643Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:00:21.643Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:01:21.674Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:01:21.674Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:01:21.675Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:01:21.675Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:02:21.619Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:02:21.619Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:02:21.991Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:02:21.991Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:02:36.325Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:02:36.325Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:02:51.408Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:02:51.408Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:03:21.589Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:03:21.589Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:03:21.590Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:03:21.590Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:04:21.682Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:04:21.682Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:04:21.683Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:04:21.683Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:05:21.753Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:05:21.753Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:05:21.753Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:05:21.753Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:06:21.841Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:06:21.841Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:06:21.842Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:06:21.842Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:07:21.911Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:07:21.911Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:07:21.911Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:07:21.912Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:07:36.413Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:07:36.414Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:07:39.305Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:07:39.305Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:08:21.877Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:08:21.877Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:08:21.877Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:08:21.877Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:09:21.761Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:09:21.762Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:09:22.012Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:09:22.012Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:10:21.868Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:10:21.868Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:10:22.170Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:10:22.170Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:11:22.014Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:11:22.014Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:11:22.016Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:11:22.016Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:12:22.124Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:12:22.124Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:12:22.124Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:12:22.124Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:12:36.415Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:12:36.415Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:12:37.351Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:12:37.351Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:13:22.045Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:13:22.045Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:13:22.046Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:13:22.047Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:14:22.152Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:14:22.152Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:14:22.153Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:14:22.153Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:15:22.043Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:15:22.043Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:15:22.045Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:15:22.045Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:16:22.111Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:16:22.111Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:16:22.477Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:16:22.477Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:17:22.335Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:17:22.336Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:17:22.337Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:17:22.337Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:17:36.434Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:17:36.434Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:18:01.356Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:18:01.356Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:18:22.360Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:18:22.360Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:18:22.361Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:18:22.361Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:19:22.206Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:19:22.206Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:19:22.492Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:19:22.492Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:20:22.350Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:20:22.350Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:20:22.351Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:20:22.351Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:21:22.396Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:21:22.396Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:21:22.397Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:21:22.397Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:22:22.522Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:22:22.522Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:22:22.522Z rhea-promise:receiver [connection-2] receiver got event: 'message'. Re-emitting the translated context.
2018-12-11T00:22:22.522Z rhea-promise:translate [connection-2] Translating the context for event: 'message'.
2018-12-11T00:22:41.790Z rhea-promise:connection [connection-2] connection got event: 'disconnected'. Re-emitting the translated context.
2018-12-11T00:22:41.790Z rhea-promise:translate [connection-2] Translating the context for event: 'disconnected'.
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
    at TLSWrap.onread (net.js:660:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] state: { wasConnectionCloseCalled: false,
  numSenders: 0,
  numReceivers: 2 }

imalao · 2018-12-13T20:55:49Z

00:37:51 was the first occurrence of the UnauthorizedError error after 00:22:41. There weren't any rhea or azure logs directly before the Unauthorized error any times I have encountered this error.

I always get the "Something is busted." error, then some time (15-30 min) passes before the "Acquiring cbs lock" message, and then the Unauthorized Error occurs.

2018-12-11T00:22:42.097Z azure:event-hubs:error [connection-2] Something is busted. State of Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver:
   Receiver {
     _events:
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session:
      Session {
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Connection],
        _session: [Session] },
     _link:
      Receiver {
        session: [Session],
        connection: [Connection],
        name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        options: [Object],
        state: [EndpointState],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 0,
        credit: 1000,
        observers: [EventEmitter],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions:
      { name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }
[info] Checking hubs are online
[info] Checking hubs are online
[info] Checking hubs are online
[info] Checking hubs are online
2018-12-11T00:37:51.172Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.
2018-12-11T00:37:51.173Z azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection.
2018-12-11T00:37:51.173Z rhea-promise:connection [connection-2] Trying to create a new amqp connection.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] connection got event: 'connection_open'. Re-emitting the translated context.
2018-12-11T00:37:51.781Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
2018-12-11T00:37:51.781Z azure:event-hubs:connectionContext [connection-2] setting 'wasConnectionCloseCalled' property of connection context to false.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] Resolving the promise with amqp connection.
2018-12-11T00:37:51.781Z azure:amqp-common:cbs [connection-2] Creating sender/receiver links on a session for $cbs endpoint.
2018-12-11T00:37:51.782Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-11T00:37:51.782Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-11T00:37:51.783Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.784Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.784Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.785Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.785Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.785Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.787Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.787Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.847Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_error'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_error'.
2018-12-11T00:37:51.944Z azure:event-hubs:error [connection-2] An error occurred for Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/1'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at Receiver.EventHubReceiver._onAmqpError (/app/node_modules/@azure/event-hubs/dist/lib/eventHubReceiver.js:78:47)
    at Receiver.emit (events.js:182:13)
    at emit (/app/node_modules/rhea-promise/dist/lib/util/utils.js:129:24)
    at Object.emitEvent (/app/node_modules/rhea-promise/dist/lib/util/utils.js:140:9)
    at Receiver._link.on (/app/node_modules/rhea-promise/dist/lib/link.js:248:25)
    at Receiver.emit (events.js:182:13)
    at Receiver.link.dispatch (/app/node_modules/rhea/lib/link.js:59:37)
    at Receiver.link.on_detach (/app/node_modules/rhea/lib/link.js:159:32)
    at Session.on_detach (/app/node_modules/rhea/lib/session.js:714:27)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.

ramya-rao-a · 2018-12-14T00:40:40Z

So there was no Acquiring cbs lock: 'negotiateClaim-e15b1b00-9e7c-fd4a-900f-e350fea197ef' for cbs auth for StreamingReceiver: or Negotiated claim for StreamingReceiver after the ECONNRESET and before the UnauthorizedError error?

ramya-rao-a · 2018-12-14T01:38:25Z

Here is an updated sequence of events:

2 receivers were created and token renewal was set up for every 45 minutes for both the receivers and the MangementClient
A connection error with code ECONNRESET occurs which closes the underlying receiver link
The SDK reacts to this by trying to reconnect any senders/receivers that are in the cache
But the SDK doesnt really reconnect the 2 receviers as it assumes that they were closed by the SDK.
- This is because we rely on the is_closed() in rhea to determine if a link was closed by the SDK.
- But this function will return true even when the link is closed by external factors.
- This results in the line "Something is busted." in the logs telling us that we were trying to re-connect a receiver whose link was closed previously.
- @amarzavery I believe we can remove the isClosed() check when trying to reconnect the receivers. The other code paths that call detached() (See _onAmqpClose) except the one for connection errors make this check anyway. This way we can ensure the receivers get reconnected on connection errors
After some time, we get the UnauthorizedError error
- The time this error is thrown matches with the time when the token for the receiver expires

Stack trace for the UnauthorizedError error goes all the way down to Session.on_detach in rhea. @grs Any idea if this is related to the token expiry?

UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/0'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at Receiver.EventHubReceiver._onAmqpError (/app/node_modules/@azure/event-hubs/dist/lib/eventHubReceiver.js:78:47)
    at Receiver.emit (events.js:182:13)
    at emit (/app/node_modules/rhea-promise/dist/lib/util/utils.js:129:24)
    at Object.emitEvent (/app/node_modules/rhea-promise/dist/lib/util/utils.js:140:9)
    at Receiver._link.on (/app/node_modules/rhea-promise/dist/lib/link.js:248:25)
    at Receiver.emit (events.js:182:13)
    at Receiver.link.dispatch (/app/node_modules/rhea/lib/link.js:59:37)
    at Receiver.link.on_detach (/app/node_modules/rhea/lib/link.js:159:32)
    at Session.on_detach (/app/node_modules/rhea/lib/session.js:714:27)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access'

grs · 2018-12-14T09:36:04Z

As mentioned in amqp/rhea#170, is_itself_closed() can be used to determine if the link was explicitly closed rather than being implicitly closed by one of its parents.

I don't fully understand the question about token expiry. I would guess from the error that it may indeed by that but the token management happens above the rhea level and I am not familiar with it.

imalao · 2018-12-14T14:59:33Z

@ramya-rao-a There was a Acquiring cbs lock after the ECONNRESET and before the UnauthorizedError:

2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
    at TLSWrap.onread (net.js:660:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] state: { wasConnectionCloseCalled: false,
  numSenders: 0,
  numReceivers: 2 }
2018-12-11T00:22:41.791Z azure:event-hubs:error [connection-2] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-12-11T00:22:42.092Z azure:event-hubs:error [connection-2] calling detached on receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0'.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The receiver is open ? -> false
2018-12-11T00:22:42.093Z azure:event-hubs:error [connection-2] calling detached on receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1'.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The receiver is open ? -> false
2018-12-11T00:22:42.093Z rhea-promise:receiver [connection-2] receiver has been closed, now closing it's session.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The session is open ? -> false
2018-12-11T00:22:42.093Z rhea-promise:receiver [connection-2] receiver has been closed, now closing it's session.
2018-12-11T00:22:42.093Z rhea-promise:error [connection-2] The session is open ? -> false
2018-12-11T00:22:42.093Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' closed.
2018-12-11T00:22:42.093Z azure:event-hubs:linkEntity [connection-2] StreamingReceiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' closed.
2018-12-11T00:22:42.095Z azure:event-hubs:error [connection-2] Something is busted. State of Receiver 'd32f0fc0-becb-4189-b572-7b934b5f6781' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/0' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver:
   Receiver {
     _events:
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session:
      Session {
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Connection],
        _session: [Session] },
     _link:
      Receiver {
        session: [Session],
        connection: [Connection],
        name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
        options: [Object],
        state: [EndpointState],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 494,
        credit: 756,
        observers: [EventEmitter],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions:
      { name: 'd32f0fc0-becb-4189-b572-7b934b5f6781',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }
2018-12-11T00:22:42.097Z azure:event-hubs:error [connection-2] Something is busted. State of Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d' with address 'iothub-ehub-pf-test-hu-1005325-78b76d275b/ConsumerGroups/$default/Partitions/1' is: { wasCloseInitiated: true,
  receiverError: undefined,
  _receiver:
   Receiver {
     _events:
      { message: [Function],
        receiver_error: [Function],
        receiver_close: [Function] },
     _eventsCount: 3,
     _maxListeners: undefined,
     actionInitiated: 0,
     type: 'receiver',
     _session:
      Session {
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        actionInitiated: 0,
        _connection: [Connection],
        _session: [Session] },
     _link:
      Receiver {
        session: [Session],
        connection: [Connection],
        name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        options: [Object],
        state: [EndpointState],
        issue_flow: false,
        local: [Object],
        remote: [Object],
        delivery_count: 0,
        credit: 1000,
        observers: [EventEmitter],
        drain: false,
        _events: [Object],
        _eventsCount: 7 },
     linkOptions:
      { name: '9d5cfb5d-df29-49b1-8c3b-a4239077874d',
        autoaccept: true,
        source: [Object],
        credit_window: 1000,
        onMessage: [Function],
        onError: [Function],
        onClose: [Function],
        onSessionError: [Function],
        onSessionClose: [Function] } } }



2018-12-11T00:37:51.172Z azure:event-hubs:linkEntity [connection-2] Acquiring cbs lock: 'negotiateCbs-9715b8b2-0776-264a-acf8-b9016309542f' for creating the cbs session while creating the ManagementClient: 'de979bba-3b79-460c-97d9-abe99bc20785' with address: '$management'.



2018-12-11T00:37:51.173Z azure:amqp-common:cbs The CBS client is trying to establish an AMQP connection.
2018-12-11T00:37:51.173Z rhea-promise:connection [connection-2] Trying to create a new amqp connection.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] connection got event: 'connection_open'. Re-emitting the translated context.
2018-12-11T00:37:51.781Z rhea-promise:translate [connection-2] Translating the context for event: 'connection_open'.
2018-12-11T00:37:51.781Z azure:event-hubs:connectionContext [connection-2] setting 'wasConnectionCloseCalled' property of connection context to false.
2018-12-11T00:37:51.781Z rhea-promise:connection [connection-2] Resolving the promise with amqp connection.
2018-12-11T00:37:51.781Z azure:amqp-common:cbs [connection-2] Creating sender/receiver links on a session for $cbs endpoint.
2018-12-11T00:37:51.782Z rhea-promise:eventhandler [connection-2] rhea-promise 'session' object is listening for events: [ 'session_open', 'session_error', 'session_close', 'settled', 'sender_error', 'sender_close', 'receiver_error', 'receiver_close' ] emitted by rhea's 'session' object.
2018-12-11T00:37:51.782Z rhea-promise:session [connection-2] Calling amqp session.begin().
2018-12-11T00:37:51.783Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.783Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.783Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.784Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.784Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_open'. Re-emitting the translated context.
2018-12-11T00:37:51.784Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_open'.
2018-12-11T00:37:51.784Z rhea-promise:sender [connection-2] sender got event: 'sender_flow'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sender_flow'.
2018-12-11T00:37:51.785Z rhea-promise:sender [connection-2] sender got event: 'sendable'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'sendable'.
2018-12-11T00:37:51.785Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.785Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.785Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.787Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.787Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] session got event: 'session_open'. Re-emitting the translated context.
2018-12-11T00:37:51.847Z rhea-promise:translate [connection-2] Translating the context for event: 'session_open'.
2018-12-11T00:37:51.847Z rhea-promise:session [connection-2] Resolving the promise with amqp session.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] rhea-promise 'sender' object is listening for events: [ 'sendable', 'sender_open', 'sender_draining', 'sender_flow', 'sender_error', 'sender_close', 'accepted', 'released', 'rejected', 'modified', 'settled' ] emitted by rhea's 'sender' object.
2018-12-11T00:37:51.847Z rhea-promise:eventhandler [connection-2] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_open'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_open'.
2018-12-11T00:37:51.943Z rhea-promise:receiver [connection-2] receiver got event: 'receiver_error'. Re-emitting the translated context.
2018-12-11T00:37:51.943Z rhea-promise:translate [connection-2] Translating the context for event: 'receiver_error'.
2018-12-11T00:37:51.944Z azure:event-hubs:error [connection-2] An error occurred for Receiver '9d5cfb5d-df29-49b1-8c3b-a4239077874d': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://ihsuprodblres076dednamespace.servicebus.windows.net/iothub-ehub-pf-test-hu-1005325-78b76d275b/consumergroups/$default/partitions/1'. TrackingId:a650324180704961b0da18f51d258c0c_G11, SystemTracker:gateway7, Timestamp:2018-12-11T00:37:51
    at Object.translate (/app/node_modules/@azure/amqp-common/dist/lib/errors.js:511:17)
    at Receiver.EventHubReceiver._onAmqpError (/app/node_modules/@azure/event-hubs/dist/lib/eventHubReceiver.js:78:47)
    at Receiver.emit (events.js:182:13)
    at emit (/app/node_modules/rhea-promise/dist/lib/util/utils.js:129:24)
    at Object.emitEvent (/app/node_modules/rhea-promise/dist/lib/util/utils.js:140:9)
    at Receiver._link.on (/app/node_modules/rhea-promise/dist/lib/link.js:248:25)
    at Receiver.emit (events.js:182:13)
    at Receiver.link.dispatch (/app/node_modules/rhea/lib/link.js:59:37)
    at Receiver.link.on_detach (/app/node_modules/rhea/lib/link.js:159:32)
    at Session.on_detach (/app/node_modules/rhea/lib/session.js:714:27)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.

ramya-rao-a · 2018-12-14T18:17:16Z

@imalao Yes, but that's for the managementClient and not the receiver which I was looking for.

@grs Thanks, we will update the code to use is_itself_closed() instead.

amarzavery · 2018-12-14T20:06:33Z

@imalao @MatejSkrbis
"1.0.8" version of "@azure/event-hubs" has been published to npm. Please install the latest version of the package and let us know your findings.

imalao · 2018-12-19T20:18:45Z

My event hub client has been running for about 4 days now with no errors!

I will post if I encounter an error again but it looks good so far. Thank you @amarzavery and @ramya-rao-a!

MatejSkrbis · 2019-01-07T08:35:07Z

I just got another UnauthorizedError 2 days ago on version "@azure/event-hubs": "1.0.8". This time I did not have debug enabled as code runs on remote machine and only error was recorded.

ramya-rao-a · 2019-01-07T20:46:11Z

Sorry about that @MatejSkrbis

Can you enable debugging and share the logs the next time this happens?

MatejSkrbis · 2019-01-08T12:57:12Z

I will try to catch it, but it can take quite some time as it is not so frequent event.

MatejSkrbis · 2019-02-01T15:22:40Z

It just happened on our server again.
Here are some logs at the time these occured:

2019-02-01T14:57:14.582Z rhea:io [connection-4] read 65 bytes
2019-02-01T14:57:14.582Z rhea:io [connection-4] got frame of size 65
2019-02-01T14:57:14.582Z rhea:frames [connection-4]:6 <- attach#12 {"name":"7834e55f-16d1-2b46-bbf0-485ca6f3472d","role":true,"source":null,"target":null} 
2019-02-01T14:57:14.582Z rhea:events [connection-4] Link got event: sender_open
2019-02-01T14:57:14.582Z rhea:io [connection-4] read 110 bytes
2019-02-01T14:57:14.582Z rhea:io [connection-4] got frame of size 110
2019-02-01T14:57:14.582Z rhea:frames [connection-4]:6 <- detach#16 {"closed":true,"error":{"condition":"amqp:not-allowed","description":"A link to connection '304158961' $cbs node has already been opened."}} 
2019-02-01T14:57:14.582Z rhea:events [connection-4] Link got event: sender_error
2019-02-01T14:57:14.582Z rhea:events [connection-4] Link got event: sender_close
2019-02-01T14:57:14.582Z rhea-promise:error [connection-4] Error occurred while creating a sender over amqp connection: c {
  value: 
   [ Typed { type: [Object], value: 'amqp:not-allowed' },
     Typed {
       type: [Object],
       value: 'A link to connection \'304158961\' $cbs node has already been opened.' },
     Typed { type: [Object], value: null } ] }.
2019-02-01T14:57:14.582Z rhea:frames [connection-4]:6 -> detach#16 {"closed":true} 
2019-02-01T14:57:14.598Z azure:event-hubs:error [connection-4] ManagementClient '97817dae-56f5-4399-bdb4-abea430bba64' with address $management, an error occurred while renewing the token: { InvalidOperationError: A link to connection '304158961' $cbs node has already been opened.
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at CbsClient.<anonymous> (service\node_modules\@azure\amqp-common\lib\cbs.ts:118:13)
    at Generator.throw (<anonymous>)
    at rejected (service\node_modules\tslib\tslib.js:105:69)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:189:7)
  name: 'InvalidOperationError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:not-allowed' }
2019-02-01T14:57:14.805Z rhea:io [connection-4] read 65 bytes
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 65
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:1 <- attach#12 {"name":"d6ca97e3-a73a-431b-8c42-13851f2b8ca7","source":null,"target":null} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_open
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:1 -> flow#13 {"incoming_window":2048,"outgoing_window":4294967295,"link_credit":1000} 
2019-02-01T14:57:14.805Z rhea:io [connection-4] read 2072 bytes
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 65
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:2 <- attach#12 {"name":"a88ecb69-84c9-4987-b96c-a219cf19d74a","source":null,"target":null} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_open
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 362
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:2 <- detach#16 {"closed":true,"error":{"condition":"amqp:unauthorized-access","description":"Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/7'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14"}} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_error
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] An error occurred for Receiver '6c9959e4-0976-4197-9e7f-64ceda1dc35d': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/7'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.
{ UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/7'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_close
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] 'receiver_close' event occurred for receiver '6c9959e4-0976-4197-9e7f-64ceda1dc35d' with address 'event-hub/ConsumerGroups/$default/Partitions/7'. The associated error is: c {
  value: 
   [ Typed { type: [Object], value: 'amqp:unauthorized-access' },
     Typed {
       type: [Object],
       value: 'Unauthorized access. \'Listen\' claim(s) are required to perform this operation. Resource: \'sb://connection-link/event-hub/consumergroups/$default/partitions/7\'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14' },
     Typed { type: [Object], value: null } ] }
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] 'receiver_close' event occurred on the receiver '6c9959e4-0976-4197-9e7f-64ceda1dc35d' with address 'event-hub/ConsumerGroups/$default/Partitions/7' and the sdk did not initiate this. The receiver is not reconnecting. Hence, calling detached from the _onAmqpClose() handler.
2019-02-01T14:57:14.805Z rhea-promise:error [connection-4] The receiver is open ? -> false
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 65
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:3 <- attach#12 {"name":"2fadec42-2806-454d-8584-7366278cf2d6","source":null,"target":null} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_open
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 362
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:3 <- detach#16 {"closed":true,"error":{"condition":"amqp:unauthorized-access","description":"Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/8'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14"}} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_error
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] An error occurred for Receiver 'ada48e56-235d-4a03-bf2b-c9172b1dbaa0': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/8'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.
{ UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/8'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_close
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] 'receiver_close' event occurred for receiver 'ada48e56-235d-4a03-bf2b-c9172b1dbaa0' with address 'event-hub/ConsumerGroups/$default/Partitions/8'. The associated error is: c {
  value: 
   [ Typed { type: [Object], value: 'amqp:unauthorized-access' },
     Typed {
       type: [Object],
       value: 'Unauthorized access. \'Listen\' claim(s) are required to perform this operation. Resource: \'sb://connection-link/event-hub/consumergroups/$default/partitions/8\'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14' },
     Typed { type: [Object], value: null } ] }
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] 'receiver_close' event occurred on the receiver 'ada48e56-235d-4a03-bf2b-c9172b1dbaa0' with address 'event-hub/ConsumerGroups/$default/Partitions/8' and the sdk did not initiate this. The receiver is not reconnecting. Hence, calling detached from the _onAmqpClose() handler.
2019-02-01T14:57:14.805Z rhea-promise:error [connection-4] The receiver is open ? -> false
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 65
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:4 <- attach#12 {"name":"ee445d8f-4bb5-423b-a5be-c80cc805450a","source":null,"target":null} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_open
2019-02-01T14:57:14.805Z rhea:io [connection-4] got frame of size 362
2019-02-01T14:57:14.805Z rhea:frames [connection-4]:1 <- detach#16 {"closed":true,"error":{"condition":"amqp:unauthorized-access","description":"Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/6'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14"}} 
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_error
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] An error occurred for Receiver '866101fa-3376-47cd-92a6-b3a6bbbdc06d': { UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/6'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }.
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] Since the user did not close the receiver and the error is not retryable, we let the user know about it by calling the user's error handler.
{ UnauthorizedError: Unauthorized access. 'Listen' claim(s) are required to perform this operation. Resource: 'sb://connection-link/event-hub/consumergroups/$default/partitions/6'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14
    at Object.translate (service\node_modules\@azure\amqp-common\lib\errors.ts:537:13)
    at Receiver.EventHubReceiver._onAmqpError (service\node_modules\@azure\event-hubs\lib\eventHubReceiver.ts:225:25)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at emit (service\node_modules\rhea-promise\lib\util\utils.ts:183:20)
    at Object.emitEvent (service\node_modules\rhea-promise\lib\util\utils.ts:195:5)
    at Receiver._link.on (service\node_modules\rhea-promise\lib\link.ts:292:11)
    at emitOne (events.js:116:13)
    at Receiver.emit (events.js:211:7)
    at Receiver.link.dispatch (service\node_modules\rhea\lib\link.js:59:37)
  name: 'UnauthorizedError',
  translated: true,
  retryable: false,
  info: null,
  condition: 'amqp:unauthorized-access' }
2019-02-01T14:57:14.805Z rhea:events [connection-4] Link got event: receiver_close
2019-02-01T14:57:14.805Z azure:event-hubs:error [connection-4] 'receiver_close' event occurred for receiver '866101fa-3376-47cd-92a6-b3a6bbbdc06d' with address 'event-hub/ConsumerGroups/$default/Partitions/6'. The associated error is: c {
  value: 
   [ Typed { type: [Object], value: 'amqp:unauthorized-access' },
     Typed {
       type: [Object],
       value: 'Unauthorized access. \'Listen\' claim(s) are required to perform this operation. Resource: \'sb://connection-link/event-hub/consumergroups/$default/partitions/6\'. TrackingId:14543c918d7a4802940d936328fea36d_G13, SystemTracker:gateway5, Timestamp:2019-02-01T14:57:14' },
     Typed { type: [Object], value: null } ] }

ramya-rao-a · 2019-02-01T18:52:27Z

@MatejSkrbis I am closing this issue as this was majorly related to the SDK not trying to reconnect after a ECONNRESET.

For the latest problem that you have, even though it says the same "Unauthorized error", I have created a new issue #186. Lets continue there.

amarzavery mentioned this issue Dec 14, 2018

receiver.is_closed() returns true when ECONNRESET error happens amqp/rhea#170

Closed

ramya-rao-a mentioned this issue Dec 14, 2018

Use isItselfClosed() to determine if sdk initiatied close #175

Merged

AlexGhiondea added Client Issues that refer to the client sdk Event Hubs bug and removed Client Issues that refer to the client sdk Event Hubs labels Jan 14, 2019

ramya-rao-a changed the title ~~Event hub client - Unauthorized access~~ Event hub client - Unauthorized access after ECONNRESET Feb 1, 2019

ramya-rao-a mentioned this issue Feb 1, 2019

Event hub client - Unauthorized access due to "InvalidOperationError: $cbs node has already been opened" when renewing token #186

Closed

ramya-rao-a closed this as completed Feb 1, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Event hub client - Unauthorized access after ECONNRESET #174

Event hub client - Unauthorized access after ECONNRESET #174

MatejSkrbis commented Nov 29, 2018 •

edited

Loading

AlexGhiondea commented Dec 4, 2018

MatejSkrbis commented Dec 5, 2018

imalao commented Dec 11, 2018 •

edited

Loading

ramya-rao-a commented Dec 13, 2018 •

edited

Loading

imalao commented Dec 13, 2018 •

edited

Loading

ramya-rao-a commented Dec 13, 2018 •

edited

Loading

imalao commented Dec 13, 2018 •

edited

Loading

imalao commented Dec 13, 2018

ramya-rao-a commented Dec 14, 2018

ramya-rao-a commented Dec 14, 2018

grs commented Dec 14, 2018

imalao commented Dec 14, 2018

ramya-rao-a commented Dec 14, 2018

amarzavery commented Dec 14, 2018 •

edited

Loading

imalao commented Dec 19, 2018

MatejSkrbis commented Jan 7, 2019

ramya-rao-a commented Jan 7, 2019

MatejSkrbis commented Jan 8, 2019

MatejSkrbis commented Feb 1, 2019

ramya-rao-a commented Feb 1, 2019

Event hub client - Unauthorized access after ECONNRESET #174

Event hub client - Unauthorized access after ECONNRESET #174

Comments

MatejSkrbis commented Nov 29, 2018 • edited Loading

AlexGhiondea commented Dec 4, 2018

MatejSkrbis commented Dec 5, 2018

imalao commented Dec 11, 2018 • edited Loading

ramya-rao-a commented Dec 13, 2018 • edited Loading

imalao commented Dec 13, 2018 • edited Loading

ramya-rao-a commented Dec 13, 2018 • edited Loading

imalao commented Dec 13, 2018 • edited Loading

imalao commented Dec 13, 2018

ramya-rao-a commented Dec 14, 2018

ramya-rao-a commented Dec 14, 2018

grs commented Dec 14, 2018

imalao commented Dec 14, 2018

ramya-rao-a commented Dec 14, 2018

amarzavery commented Dec 14, 2018 • edited Loading

imalao commented Dec 19, 2018

MatejSkrbis commented Jan 7, 2019

ramya-rao-a commented Jan 7, 2019

MatejSkrbis commented Jan 8, 2019

MatejSkrbis commented Feb 1, 2019

ramya-rao-a commented Feb 1, 2019

MatejSkrbis commented Nov 29, 2018 •

edited

Loading

imalao commented Dec 11, 2018 •

edited

Loading

ramya-rao-a commented Dec 13, 2018 •

edited

Loading

imalao commented Dec 13, 2018 •

edited

Loading

ramya-rao-a commented Dec 13, 2018 •

edited

Loading

imalao commented Dec 13, 2018 •

edited

Loading

amarzavery commented Dec 14, 2018 •

edited

Loading