Closed MatejSkrbis closed 6 years ago
@MatejSkrbis - Thanks for reporting this issue. Current version of the azure-event-hubs
sdk does not handle disconnect errors at any level. I just merged couple of PRs yesterday in the master branch that handle disconnects.
I am testing this right now. It would great if you could test the code merged in master branch and let me know how the sdk behaves.
Here are the steps to build the sdk from scratch and it is super simple
npm i -g typescript (in case you do not have typescript installed globally)
git clone https://github.com/Azure/azure-event-hubs-node.git
cd azure-eventhubs-node\client
npm i
npm run build
That is it. That should get everything ready for you.
In your application's package.json
"azure-event-hubs": "../azure-event-hubs-node/client" // relative path to the cloned repo
Let me know your findings.
I've tried to build and use this SDK. It seems it handles the case I mentioned above. After 30 min of inactivity the connection gets broken and then reestablished as it is expected. [connection-1] disconnected
is no longer displayed and I am still able to send packages through connection.
That is awesome. Thank you for testing the changes. Shall publish a package tomorrow morning with updates.
@MatejSkrbis - azure-event-hubs@0.2.4
has been published.
I left the connection over night and it seems it didn't work in the morning when I tried sending message. I have attached the debug log if it helps.
2018-07-17T06:13:00.608Z azure:event-hubs:sender [connection-1] Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4', trying to send EventData[].
2018-07-17T06:13:00.609Z azure:amqp-common:datatransformer [encode] The given message body that needs to be encoded is: {...}
2018-07-17T06:13:00.609Z azure:amqp-common:datatransformer [encode] The encoded message body is: Section {
typecode: 117,
content: <Buffer ... >,
multiple: undefined }.
2018-07-17T06:13:00.610Z rhea:message Encoding section 1 of 5: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:00.610Z rhea:message Encoding section 2 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 113] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 113 } }
2018-07-17T06:13:00.610Z rhea:message Encoding section 3 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:00.610Z rhea:message Encoding section 4 of 5: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: '2150868a-b2ab-40cb-8028-70552e4eb6e9' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:00.610Z rhea:message Encoding section 5 of 5: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 35 30 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 34 30 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:00.610Z rhea:message encoded 353 bytes
2018-07-17T06:13:00.611Z rhea:message Encoding section 1 of 4: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:00.611Z rhea:message Encoding section 2 of 4: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:00.611Z rhea:message Encoding section 3 of 4: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: '2150868a-b2ab-40cb-8028-70552e4eb6e9' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:00.611Z rhea:message Encoding section 4 of 4: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 00 53 70 45 00 53 71 d1 00 00 00 04 00 00 00 00 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 32 31 35 30 38 36 38 61 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:00.611Z rhea:message encoded 427 bytes
2018-07-17T06:13:00.611Z azure:event-hubs:sender [connection-1]Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4', sending encoded batch message. <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 32 31 35 30 38 36 38 61 2d 62 32 61 62 2d 34 30 63 62 2d 38 ... >
2018-07-17T06:13:00.612Z azure:amqp-common:retry Retry attempt number: 1
2018-07-17T06:13:00.612Z azure:event-hubs:sender [connection-1] Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4', credit: 994 available: 2042
2018-07-17T06:13:00.612Z azure:event-hubs:sender [connection-1] Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4', sending message: <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 32 31 35 30 38 36 38 61 2d 62 32 61 62 2d 34 30 63 62 2d 38 ... >
2018-07-17T06:13:00.612Z azure:event-hubs:sender [connection-1] Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4', sent message with delivery id: 6 and tag: 2150868a-b2ab-40cb-8028-70552e4eb6e9
2018-07-17T06:13:00.613Z rhea:events Connection got event: disconnected
2018-07-17T06:13:00.613Z azure:event-hubs:connectionContext [connection-1] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-07-17T06:13:00.613Z rhea:frames [connection-1]:5 -> transfer#14 {"delivery_id":6,"delivery_tag":"2150868a-b2ab-40cb-8028-70552e4eb6e9","message_format":2147563264} <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 32 31 35 30 38 36 38 61 2d 62 32 61 62 2d 34 30 63 62 2d 38 ... >
2018-07-17T06:13:00.613Z rhea:raw [connection-1] SENT: 495 00000 ...
2018-07-17T06:13:00.913Z azure:event-hubs:connectionContext [connection-1] calling detached on sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4' with address 'test-hub/Partitions/0'.
2018-07-17T06:13:00.914Z azure:event-hubs:sender [connection-1] close() method of Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4' with address 'test-hub/Partitions/0' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
2018-07-17T06:13:00.914Z azure:event-hubs:sender Creating sender with options: { name: '75333c43-0139-4a2c-bf00-80523282956d',
target: { address: 'test-hub/Partitions/0' },
onError: [Function],
onClose: [AsyncFunction] }
2018-07-17T06:13:00.915Z azure:amqp-common:retry Retry attempt number: 1
2018-07-17T06:13:00.916Z azure:amqp-common:retry Success, after attempt number: 1.
2018-07-17T06:13:00.916Z azure:amqp-common:retry Success result: undefined
2018-07-17T06:13:30.607Z azure:event-hubs:sender [connection-1] Sender '75333c43-0139-4a2c-bf00-80523282956d', trying to send EventData[].
2018-07-17T06:13:30.608Z azure:amqp-common:datatransformer [encode] The given message body that needs to be encoded is: {...}
2018-07-17T06:13:30.608Z azure:amqp-common:datatransformer [encode] The encoded message body is: Section {
typecode: 117,
content: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >,
multiple: undefined }.
2018-07-17T06:13:30.608Z azure:amqp-common:datatransformer [encode] The given message body that needs to be encoded is: {...}
2018-07-17T06:13:30.609Z azure:amqp-common:datatransformer [encode] The encoded message body is: Section {
typecode: 117,
content: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >,
multiple: undefined }.
2018-07-17T06:13:30.609Z azure:amqp-common:datatransformer [encode] The given message body that needs to be encoded is: {...}
2018-07-17T06:13:30.609Z azure:amqp-common:datatransformer [encode] The encoded message body is: Section {
typecode: 117,
content: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >,
multiple: undefined }.
2018-07-17T06:13:30.610Z rhea:message Encoding section 1 of 5: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:30.610Z rhea:message Encoding section 2 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 113] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 113 } }
2018-07-17T06:13:30.610Z rhea:message Encoding section 3 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:30.610Z rhea:message Encoding section 4 of 5: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: '7a2d8a3c-2ad4-4796-bfd3-7e519b6604e7' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:30.610Z rhea:message Encoding section 5 of 5: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.610Z rhea:message encoded 353 bytes
2018-07-17T06:13:30.611Z rhea:message Encoding section 1 of 5: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:30.611Z rhea:message Encoding section 2 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 113] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 113 } }
2018-07-17T06:13:30.611Z rhea:message Encoding section 3 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:30.611Z rhea:message Encoding section 4 of 5: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: '804c2328-8458-4285-aafb-98a97cc8553f' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:30.611Z rhea:message Encoding section 5 of 5: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.611Z rhea:message encoded 353 bytes
2018-07-17T06:13:30.611Z rhea:message Encoding section 1 of 5: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:30.612Z rhea:message Encoding section 2 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 113] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 113 } }
2018-07-17T06:13:30.612Z rhea:message Encoding section 3 of 5: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:30.612Z rhea:message Encoding section 4 of 5: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: 'd0140ffe-d7d2-43c6-80a5-b6cba57c906d' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:30.612Z rhea:message Encoding section 5 of 5: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 22 7b 5c 22 6c 61 74 69 74 75 64 65 5c 22 3a 33 31 2c 5c 22 6c 6f 6e 67 69 74 75 64 65 5c 22 3a 37 35 2c 5c 22 74 69 6d 65 73 74 61 6d 70 5c 22 3a 31 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.612Z rhea:message encoded 353 bytes
2018-07-17T06:13:30.612Z rhea:message Encoding section 1 of 6: Typed { type: TypeDesc { name: 'List0', typecode: 69, width: 0, category: 1, create: { [Function] typecode: 69 } }, value: [], descriptor: { [Number: 112] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 112 } }
2018-07-17T06:13:30.613Z rhea:message Encoding section 2 of 6: Typed { type: TypeDesc { name: 'Map32', typecode: 209, width: 4, category: 3, create: { [Function] typecode: 209 } }, value: [], descriptor: { [Number: 114] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 114 } }
2018-07-17T06:13:30.613Z rhea:message Encoding section 3 of 6: Typed { type: TypeDesc { name: 'List32', typecode: 208, width: 4, category: 3, create: { [Function] typecode: 208 } }, value: [ Typed { type: [Object], value: '7a2d8a3c-2ad4-4796-bfd3-7e519b6604e7' } ], descriptor: { [Number: 115] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 115 } }
2018-07-17T06:13:30.613Z rhea:message Encoding section 4 of 6: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 00 53 70 45 00 53 71 d1 00 00 00 04 00 00 00 00 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 37 61 32 64 38 61 33 63 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.613Z rhea:message Encoding section 5 of 6: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 00 53 70 45 00 53 71 d1 00 00 00 04 00 00 00 00 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 38 30 34 63 32 33 32 38 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.613Z rhea:message Encoding section 6 of 6: Typed { type: TypeDesc { name: 'Vbin32', typecode: 176, width: 4, category: 2, create: { [Function] typecode: 176 } }, value: <Buffer 00 53 70 45 00 53 71 d1 00 00 00 04 00 00 00 00 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 64 30 31 34 30 66 66 65 ... >, descriptor: { [Number: 117] type: TypeDesc { name: 'SmallUlong', typecode: 83, width: 1, category: 1, read: [Function: read], write: [Function: write], create: [Object] }, value: 117 } }
2018-07-17T06:13:30.613Z rhea:message encoded 1149 bytes
2018-07-17T06:13:30.614Z azure:event-hubs:sender [connection-1]Sender '75333c43-0139-4a2c-bf00-80523282956d', sending encoded batch message. <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 37 61 32 64 38 61 33 63 2d 32 61 64 34 2d 34 37 39 36 2d 62 ... >
2018-07-17T06:13:30.614Z azure:amqp-common:retry Retry attempt number: 1
2018-07-17T06:13:30.614Z azure:event-hubs:sender [connection-1] Sender '75333c43-0139-4a2c-bf00-80523282956d', credit: 993 available: 2041
2018-07-17T06:13:30.614Z azure:event-hubs:sender [connection-1] Sender '75333c43-0139-4a2c-bf00-80523282956d', sending message: <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 37 61 32 64 38 61 33 63 2d 32 61 64 34 2d 34 37 39 36 2d 62 ... >
2018-07-17T06:13:30.614Z azure:event-hubs:sender [connection-1] Sender '75333c43-0139-4a2c-bf00-80523282956d', sent message with delivery id: 7 and tag: 7a2d8a3c-2ad4-4796-bfd3-7e519b6604e7
2018-07-17T06:13:30.615Z rhea:events Connection got event: disconnected
2018-07-17T06:13:30.615Z azure:event-hubs:connectionContext [connection-1] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-07-17T06:13:30.616Z rhea:frames [connection-1]:5 -> transfer#14 {"delivery_id":7,"delivery_tag":"7a2d8a3c-2ad4-4796-bfd3-7e519b6604e7","message_format":2147563264} <Buffer 00 53 70 45 00 53 72 d1 00 00 00 04 00 00 00 00 00 53 73 d0 00 00 00 2a 00 00 00 01 a1 24 37 61 32 64 38 61 33 63 2d 32 61 64 34 2d 34 37 39 36 2d 62 ... >
2018-07-17T06:13:30.616Z rhea:raw [connection-1] SENT: 1217 00000 ...
2018-07-17T06:13:30.916Z azure:event-hubs:connectionContext [connection-1] calling detached on sender '75333c43-0139-4a2c-bf00-80523282956d' with address 'test-hub/Partitions/0'.
2018-07-17T06:13:30.916Z azure:event-hubs:sender [connection-1] close() method of Sender '75333c43-0139-4a2c-bf00-80523282956d' with address 'test-hub/Partitions/0' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
2018-07-17T06:13:30.916Z azure:event-hubs:sender Creating sender with options: { name: '5035c619-1257-4e9e-a24a-65b9ed0cd289',
target: { address: 'test-hub/Partitions/0' },
onError: [Function],
onClose: [AsyncFunction] }
2018-07-17T06:13:30.916Z azure:amqp-common:retry Retry attempt number: 1
2018-07-17T06:13:30.917Z azure:amqp-common:retry Success, after attempt number: 1.
2018-07-17T06:13:30.917Z azure:amqp-common:retry Success result: undefined
FYI, You can set the environment variable like this
export DEBUG=azure*,rhea*,-rhea:raw,-rhea:message,-azure:amqp-common:datatransformer
This will not log the message and data transformer encoding statements which tend to be boring and consume lot of lines in the current situation. I just learnt this from running my long running tests where I was more interested in the error events and the raw frames.
Something does not look right.
At
2018-07-17T06:13:00.613Z rhea:events Connection got event disconnected.
SDK detected that this is a case to bring it back up.
2018-07-17T06:13:00.613Z azure:event-hubs:connectionContext [connection-1] connection.close() was not called from the sdk and there were some sender or receiver links or both. We should reconnect.
2018-07-17T06:13:00.913Z azure:event-hubs:connectionContext [connection-1] calling detached on sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4' with address 'test-hub/Partitions/0'.
2018-07-17T06:13:00.914Z azure:event-hubs:sender [connection-1] close() method of Sender '6f16761e-99aa-4a45-b38a-5c26c2ca12f4' with address 'test-hub/Partitions/0' was not called. There was no accompanying error as well. This is a candidate for re-establishing the sender link.
Ahh and now I see the bug... I just saw the log statement from retry function that the attempt was successful. Ideally, we would have seen debug statements from rhea, where it would re-establish the sender links.. This does not happen because, I am checking whether the sender is open or not over here and the _init()
is called from detached
method here.
2018-07-17T06:13:00.916Z azure:amqp-common:retry Success, after attempt number: 1.
So even though the connection receives the disconnected event, the sender and receiver link in rhea still think that they are open. @grs - What do you think about this? /cc @princjef
I have tried running over night again with those debug options you posted. This time the connection was still functional and no rhea:events Connection got event: disconnected
were seen in logs. So generally it seems as it's working but there might be an edge case that is causing this disconnection events.
I see. Shall keep the issue open for now. Will monitor it in my tests to see if I can repro this.
What I fail to understand from the previous logs is:
At present the 'open' state of links, sessions and connections is tracking whether the endpoint was closed at the AMQP level, and is distinct from disconnected. That state is then used to determine whether to re-establish on reconnect.
However I have committed a change that alters this (see https://github.com/amqp/rhea/issues/101) such that is_open() is always false when disconnected (and the desired state is tracked separately).
@MatejSkrbis - The edge case should have been fixed. I made some minor updates in the sdk and @grs helped in fixing the issue in the protocol library by ensuring that the state of the sender/receiver is closed, once the connection receives the "disconnected" event. I have merged the PR to the master branch. Feel free to pull the latest updates from master and test the new bits.
This issue has been resolved. Hence closing it. A new version with updated changes will be published shortly.
In which release will this patch get merged? If not, already done..
Also,, what are the detailed instructions to download this patch include it in my project? I saw the instructions to build the package.. should I just copy the files into my project there after?
@sharath-srinivasan - This issue has been fixed. Please install the latest version of "azure-event-hubs"
. npm install azure-event-hubs
should install 0.2.7 version of the package. This should have the fix in it. If the issue persists, then please feel free to open another issue.
When connecting to event hub and sending some packages and then waiting for 30 minutes without sending anything client gets disconnected.
For every minute after 35 minutes
[connection-1] disconnected
is printed in console. Bellow you will find some debug logs.No message is sent if client tries to send after 35 minutes. I can't find a way how to handle such error as there are no example and neither does client have any such exposed methods/callbacks. I would expect library to handle such cases (if not can you please tell me how to handle them).
I'm using windows 10 with "azure-event-hubs": "0.2.3", node version: 8.9.4