OperationTimeoutError: while closing the connection

[GaikwadPratik]

While working with rhea-promise, I've to send tons of message on either dynamic topics or to queues, I use the code from sender example. The only variable is target address. As shown in the example, I am closing the sender after sending each message as it targets to different queue.

After sending few messages, I start to get below error after every message that I sent.

"name": "OperationTimeoutError",
"condition": "amqp:operation-timeout",
"description": "Unable to close the amqp %s 910d1d15-ba1a-ba49-831b-4d88470be3b0 
                due to operation timeout."

If I remove, closing of sender explicitly then I don't see the error. Should I leave sender open for the life cycle of my application? Currently I am leaving associated connection open as long as my application is running. Do I have to close connection?

[GaikwadPratik]

@amarzavery, @grs,

Can you guys provide any insights on this?

[grs]

What broker are you using?

It should be fine to close the link after every message (though inefficient if you use that same address frequently).

Either the broker is failing to return a detach frame when the client sends its detach, or there is some bug in the client library's handling of that detach.

How reproducible is it for you? The best thing would be to get a protocol trace from the broker side if possible, to show which side the problem is on.

[GaikwadPratik]

@grs , @amarzavery ,
It is not very easy to reproduce but it pops every now and then. Recently I started seeing this also

 OperationTimeoutError: Unable to close the amqp session due to operation timeout.
        at ontimeout (timers.js:436:11)
        at tryOnTimeout (timers.js:300:5)
        at listOnTimeout (timers.js:263:5)
        at Timer.processTimers (timers.js:223:10)

I removed the manual closing of the link to see if the error stops. How do I get the protocol trace from broker? We use Qpid C++ broker.

[grs]

You can get protocol trace from broker with command line option --log-enable trace+:Protocol (or env var QPID_LOG_ENABLE=trace+:Protocol).

[GaikwadPratik]

@grs , @amarzavery

Well, I managed to reproduce this.Assuming default timeout is a min, here are the logs(from DEBUG=rhea*) before a min or two when I get operationtimeout message:

optimeout.log

Let me know if you guys need anymore information

[grs]

Error is 'Unable to close the amqp session due to operation timeout' but an end is received fro every end sent out, and there are the expected number of session_close events in rhea and rhea-promise.

Possibly some timer not being reset?

[GaikwadPratik]

@grs ,

These errors are being thrown from session and link. I've seen both of them on separate occasions.

[amarzavery]

@grs - I was looking through the logs to see the correlation between operation timeout errors and session close (-> end) (<- end) frames. However, it is cumbersome to do that.

It would be nice if the session object can have an id or name property that can uniquely identify the session. Then we can log that id for the session in all the session related log statements. This will make it very convenient to find the root cause.

@GaikwadPratik - For debugging such issues, log statements with rhea:message and rhea:raw are pure noise.
If you set the DEBUG environment variable like this, then log statements from raw and message modules of rhea will not be logged.

export DEBUG=rhea*,-rhea:raw,-rhea:message

[grs]

@amarzavery there is the channel number which (locally) is unique to a given session at any time, so e.g. in [connection-1]:10 <- end#17 the channel is 10. This will be true for all other frames sent on the session. The channel is not always the same in each direction though, so you have session.local.channel and session.remote.channel.

[amarzavery]

I see. How would one know the direction to log the remote v/s local channel? These are the inner details of session and that is why we did not expose these types from the Session interface in rhea.

Having an optional property named sessionId or id or name that a user can set if required to uniquely identify the session will be very useful.

If you like the idea, then I can send a PR.

The intent is throw an Error with the message "Unable to close the amqp session 'blah blah' due to operation timeout". Would also love to log this session identifier in the every log statement on the session object. Thus making bug detection a little easier.

[amarzavery]

@GaikwadPratik - Creating links is an expensive operation w.r.t time in the context of sending lot of messages. If you leave the link open that should be fine. The link will die, if the underlying session or connection dies. If the link is idle for sometime, then after a predefined amount of time the server sends a detach with the right error message. At that time, you can catch the error and try to reconnect the link if necessary or do nothing about it. We do the same in Azure ServiceBus Sender over here.

[GaikwadPratik]

@amarzavery ,

here are the reduced logs(newly created) with whatever settings you sent above:

optimeout.log

[grs]

@amarzavery there is no such identifier at the protocol level and I'm not keen on something completely artificial, which would be hard to log at the frame level. You could create an identifier by combining the two handles. There could be a method on session to do that to make it simple. That along with the connection id it belongs to would then identify the session in question.

[GaikwadPratik]

@GaikwadPratik - Creating links is an expensive operation w.r.t time in the context of sending lot of messages. If you leave the link open that should be fine. The link will die, if the underlying session or connection dies. If the link is idle for sometime, then after a predefined amount of time the server sends a detach with the right error message. At that time, you can catch the error and try to reconnect the link if necessary or do nothing about it. We do the same in Azure ServiceBus Sender over here.

@amarzavery ,

I tried leaving the links open, the problem was that since I am working with dynamic queues. They are not deleted automatically and hence their number grows exponentially and thus causing qpid broker to stop processing. The only for us was to close the underlying connection which would destroy them as you mentioned above. @grs has mentioned them not closing if same address is being used a lot. Is there any example you or @grs have that I can refer for reusing the same link?

[amarzavery]

Just maintain a map of senders created in your application, where the key in the map is the sender's address and the value is the sender object. Before sending the message, I guess you would know where to send the message to. If the sender for that address is already created then you can reuse the sender link.

address is one of the options provided inside the target property while creating the sender.

[GaikwadPratik]

@amarzavery ,

that's what I was working on as we started to have a discussion today. :) I was just curious if there was any alternative which I haven't thought of.

[grs]

Depending on the broker you can also use the so called 'anonymous' sender. In rhea you can do that easily by using the Connection level send() method. Just ensure the message has the 'to' field set to the target address.

[GaikwadPratik]

@grs ,

That's what I am doing right now also. Even after that dynamic queue weren't getting cleaned up. That is the main reason I started raising disconnect events manually.

[grs]

Not from the trace you aren't. The Connection.send() in rhea opens only one link (on the default session). That option may not be available in rhea-promise of course, just mentioning it as one common way of handling the case where you need to send messages to diverse addresses.

[amarzavery]

rhea-promise creates a session for every link to keep things simple. However, if you want to have everything created on the same session then that is possible as well.

const connection: Connection = new Connection({... the connection options ...});
const session = await connection.createSession();
const sender = await connection.createSender({
   session: session,
  ... other options that can be provided,
});
const receiver = await connection.createReceiver({
   session: session,
  ... other options that can be provided,
});

You can keep on using the same session for all the sender and receiver links.

[GaikwadPratik]

@amarzavery ,

Do I have to explicitly create session from connection and pass that along or is it enough to create sender/receiver from same connection?

[amarzavery]

is it enough to create sender/receiver from same connection

I think that is what you must be doing now. If you do not provide the session, a new session will be created every time you call createSender() or createReceiver().

Check this.

Or you can do this as well, where you create the session and then keep on creating new senders and receivers off that session

const connection: Connection = new Connection({... the connection options ...});
const session = await connection.createSession();
const sender = await session.createSender({
... options that can be provided to create sender,
});
const receiver = await session.createReceiver({
  ... options that can be provided to create receiver,
});

[GaikwadPratik]

@amarzavery ,

here you go... There are bunch of them in this log...

optimeout.log

Hopefully these are good and have more info than last... :)

[amarzavery]

Thank you! Looking at the logs now.

[grs]

Looks like the connection gets disconnected before those sessions are closed.

[amarzavery]

@grs - That is true. Hence added handlers for disconnected event while opening and while closing a connection/session/link.

• While closing, it clears the timer and logs the error.
• While opening, it clears the timer and rejects the Promise with an appropriate error message.

The logs are for about 7 mins. I saw 7 disconnects due to Protocol Error. @grs - Do you know what could be the reason for such frequent disconnects in Qpid?

[grs]

@amarzavery the protocol error is I think being raised on the client side, and that is causing the connection to be dropped. The event should have an error object as the context with more details of the issue rhea encountered.

[amarzavery]

@grs - Received new log statements from @GaikwadPratik , after making some modifications to the log statements in rhea-promise.

Changes in the source code

Added a handler on the connection object for disconnected event, while closing the link

. . .
const onDisconnected = (context: RheaEventContext) => {
   removeListeners();
   const error = context.connection && context.connection.error
       ? context.connection.error
       : context.error;
   log.error("[%s] Connection got disconnected while closing amqp %s '%s' on amqp " +
      "session '%s': %O.", this.connection.id, this.type, this.name, this.session.id, error);
   };
. . .
this._link.connection.once(ConnectionEvents.disconnected, onDisconnected);

Log Statements

Connection got disconnected while closing amqp sender 'd43ce454-73f4-3a47-b94f-e765521b21fe--sender-server' on amqp session 'local-15_remote-14_connection-1': undefined.

. . .
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea:frames [connection-1]:15 -> attach#12 {"name":"d43ce454-73f4-3a47-b94f-e765521b21fe--sender-server","source":["hive.guest.events",null,null,null,true],"target":[]}
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea:io [connection-1] read 169 bytes
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea:io [connection-1] got frame of size 124
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea:frames [connection-1]:14 <- attach#12 {"name":"d43ce454-73f4-3a47-b94f-e765521b21fe--sender-server","role":true,"snd_settle_mode":2,"source":[null,0,null,0,false],"target":[null,0,null,0,false]}
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea:events [connection-1] Connection got event: protocol_error
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.294Z rhea-promise:connection [connection-1] connection 'connection-1' got event: 'protocol_error'. Re-emitting the translated context.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.295Z rhea-promise:translate [] Translating the context for event: 'protocol_error'.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.297Z rhea:reconnect [connection-1] Scheduled reconnect in 100ms
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.297Z rhea:events [connection-1] Connection got event: disconnected
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.297Z rhea-promise:connection [connection-1] connection 'connection-1' got event: 'disconnected'. Re-emitting the translated context.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.297Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.297Z rhea-promise:error [connection-1] Connection got disconnected while closing amqp sender 'd43ce454-73f4-3a47-b94f-e765521b21fe--sender-server' on amqp session 'local-15_remote-14_connection-1': undefined.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.309Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object 'local-14_remote-undefined_connection-1' 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.
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.309Z rhea-promise:session [connection-1] Calling amqp session.begin().
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.397Z rhea:reconnect [connection-1] reconnecting...
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.400Z rhea:io [connection-1] connected ::1:32962 -> ::1:5672
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.400Z rhea:frames [connection-1] -> { protocol_id: 3, major: 1, minor: 0, revision: 0 }
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.406Z rhea:io [connection-1] read 35 bytes
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.407Z rhea:frames [connection-1] <- { protocol_id: 3, major: 1, minor: 0, revision: 0 }
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.407Z rhea:io [connection-1] got frame of size 27
Jun 19 14:19:29 hive1 node[31390]: 2019-06-19T14:19:29.407Z rhea:frames [connection-1]:0 <- sasl_mechanisms#40 {"sasl_server_mechanisms":"PLAIN"}
. . . 

Question for you

1. Why is the error undefined for "disconnected" event? I am looking at context.connection.error as well as context.error?
2. Is it safe to assume that a disconnected event will always follow after protocol_error event?
3. While listening for protocol_error event, the error will be present in which property of the context?

[grs]

1. it seems at present the protocol-error is not recorded as the reason for the disconnect
2. yes
3. the error is the only object passed to the handler (i.e. it is the context)

[amarzavery]

Follow up question: When the disconnected event is fired, how to find out the reason of disconnect in the event handler for "disconnected" event?

[grs]

It should be in an 'error' field on the context to the disconnected event.

[amarzavery]

@grs - Exactly, and I don't see it there. I am checking for error at two places

• context.connection.error and
• context.error
  and still the error is undefined. Could this be a bug in rhea?

As you can see in the source code

const error = context.connection && context.connection.error
       ? context.connection.error
       : context.error;
   log.error("[%s] Connection got disconnected while closing amqp %s '%s' on amqp " +
      "session '%s': %O.", this.connection.id, this.type, this.name, this.session.id, error);
   };

Output:

[connection-1] Connection got disconnected while closing amqp sender 'd43ce454-73f4-3a47-b94f-e765521b21fe--sender-server' on amqp session 'local-15_remote-14_connection-1': undefined.

[grs]

Yes, as I mentioned in response to question 1 above, the protocol_error appears not to be getting recorded as the reason for the disconnect. That is indeed a bug. However you can get the error by handling the protocol_error and logging the error provided for now.

[amarzavery]

Ah I see.. Sorry, I misinterpreted that statement. Thanks for clarifying.

Any tentative timeline, on when the bug will be fixed?

[grs]

Probably next week.

[amarzavery]

Hey @grs - Got the updated logs of the next test run from @GaikwadPratik after logging the details of ProtocolError.

The Error is [ProtocolError: attach received on invalid channel 58].
Two sessions were into play on the same remote channel 58.

• 'local-58_remote-58_connection-1'
• 'local-59_remote-58_connection-1'
  While the first one was being closed, the second one was being opened. It is at that time, we see the ProtocolError as rhea thinks that attach was received on an invalid (remote) channel 58...

Posting the relevant section (line 3149 - 3243) of the logs here for details

2019-06-19T19:43:08.665Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object 'local-58_remote-undefined_connection-1' 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.
2019-06-19T19:43:08.665Z rhea-promise:session [connection-1] Calling amqp session.begin().
2019-06-19T19:43:08.665Z rhea:frames [connection-1]:58 -> begin#11 {"incoming_window":2048,"outgoing_window":4294967295}
2019-06-19T19:43:08.668Z rhea:io [connection-1] read 35 bytes
2019-06-19T19:43:08.668Z rhea:io [connection-1] got frame of size 35
2019-06-19T19:43:08.668Z rhea:frames [connection-1]:58 <- begin#11 {"remote_channel":58,"incoming_window":2147483647,"outgoing_window":2147483647}
2019-06-19T19:43:08.668Z rhea:events [connection-1] Session got event: session_open
2019-06-19T19:43:08.668Z rhea-promise:session [connection-1] session 'local-58_remote-58_connection-1' got event: 'session_open'. Re-emitting the translated context.
2019-06-19T19:43:08.668Z rhea-promise:translate [connection-1] Translating the context for event: 'session_open'.
2019-06-19T19:43:08.668Z rhea-promise:session [connection-1] Resolving the promise with amqp session 'local-58_remote-58_connection-1'.
2019-06-19T19:43:08.668Z rhea-promise:session [connection-1] Added event handler for event 'session_error' on rhea-promise 'session: local-58_remote-58_connection-1', while creating the sender.
2019-06-19T19:43:08.668Z 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.
2019-06-19T19:43:08.668Z rhea-promise:eventhandler [connection-1] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2019-06-19T19:43:08.669Z rhea:frames [connection-1]:58 -> attach#12 {"name":"570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server","source":["hive.fabric.events",null,null,null,true],"target":[]}
2019-06-19T19:43:08.669Z rhea:io [connection-1] read 169 bytes
2019-06-19T19:43:08.672Z rhea:io [connection-1] got frame of size 124
2019-06-19T19:43:08.672Z rhea:frames [connection-1]:58 <- attach#12 {"name":"570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server","role":true,"snd_settle_mode":2,"source":[null,0,null,0,false],"target":[null,0,null,0,false]}
2019-06-19T19:43:08.672Z rhea:events [connection-1] Link got event: sender_open
2019-06-19T19:43:08.672Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'sender_open'. Re-emitting the translated context.
2019-06-19T19:43:08.672Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_open'.
2019-06-19T19:43:08.672Z rhea:io [connection-1] got frame of size 45
2019-06-19T19:43:08.672Z rhea:frames [connection-1]:58 <- flow#13 {"incoming_window":2147483647,"outgoing_window":2147483647,"link_credit":500}
2019-06-19T19:43:08.673Z rhea:events [connection-1] Link got event: sender_flow
2019-06-19T19:43:08.673Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'sender_flow'. Re-emitting the translated context.
2019-06-19T19:43:08.673Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_flow'.
2019-06-19T19:43:08.673Z rhea:events [connection-1] Link got event: sendable
2019-06-19T19:43:08.673Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'sendable'. Re-emitting the translated context.
2019-06-19T19:43:08.673Z rhea-promise:translate [connection-1] Translating the context for event: 'sendable'.
2019-06-19T19:43:08.673Z rhea-promise:sender [connection-1] Resolving the promise with amqp sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' on amqp session 'local-58_remote-58_connection-1'.
2019-06-19T19:43:08.673Z rhea-promise:error [connection-1] The sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' on amqp session 'local-58_remote-58_connection-1' is open ? -> true
2019-06-19T19:43:08.674Z rhea:frames [connection-1]:58 -> transfer#14 {"delivery_tag":{"type":"Buffer","data":[48]}} <Buffer 00 53 70 d0 00 00 00 0b 00 00 00 03 40 40 70 00 00 27 10 00 53 73 d0 00 00 00 8b 00 00 00 06 40 40 a1 5a 38 34 36 62 34 61 63 37 2d 30 35 65 65 2d 62 ... >
2019-06-19T19:43:08.684Z rhea:frames [connection-1]:58 -> detach#16 {"closed":true}
2019-06-19T19:43:08.684Z rhea:io [connection-1] read 398 bytes
2019-06-19T19:43:08.684Z rhea:io [connection-1] got frame of size 45
2019-06-19T19:43:08.684Z rhea:frames [connection-1]:58 <- flow#13 {"next_incoming_id":1,"incoming_window":2147483647,"outgoing_window":2147483647,"delivery_count":1,"link_credit":500}
2019-06-19T19:43:08.688Z rhea:io [connection-1] got frame of size 29
2019-06-19T19:43:08.688Z rhea:frames [connection-1]:58 <- disposition#15 {"role":true,"settled":true,"state":[]}
2019-06-19T19:43:08.688Z rhea:events [connection-1] Received disposition for outgoing transfers
2019-06-19T19:43:08.688Z rhea:io [connection-1] got frame of size 301
2019-06-19T19:43:08.688Z rhea:frames [connection-1]:3 <- transfer#14 {"delivery_id":123,"delivery_tag":{"type":"Buffer","data":[0,0,0,123]},"settled":true} <Buffer 00 53 70 c0 0a 04 42 50 04 70 00 00 75 2f 41 00 53 73 d0 00 00 00 c2 00 00 00 06 a1 24 61 65 35 31 30 62 35 30 2d 66 34 65 34 2d 65 34 34 66 2d 62 63 ... >
2019-06-19T19:43:08.696Z rhea:events [connection-1] Link got event: message
2019-06-19T19:43:08.698Z rhea-promise:receiver [connection-1] receiver '708531a9-0eaa-3241-874e-e81c44090e8a--receiver-server' got event: 'message'. Re-emitting the translated context.
2019-06-19T19:43:08.698Z rhea-promise:translate [connection-1] Translating the context for event: 'message'.
2019-06-19T19:43:08.698Z rhea:io [connection-1] got frame of size 23
2019-06-19T19:43:08.698Z rhea:frames [connection-1]:58 <- detach#16 {"closed":true}
2019-06-19T19:43:08.699Z rhea:events [connection-1] Link got event: sender_close
2019-06-19T19:43:08.702Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'sender_close'. Re-emitting the translated context.
2019-06-19T19:43:08.702Z rhea-promise:translate [connection-1] Translating the context for event: 'sender_close'.
2019-06-19T19:43:08.702Z rhea-promise:sender [connection-1] Resolving the promise as the sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' on amqp session 'local-58_remote-58_connection-1' has been closed.
2019-06-19T19:43:08.702Z rhea:events [connection-1] Link got event: accepted
2019-06-19T19:43:08.702Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'accepted'. Re-emitting the translated context.
2019-06-19T19:43:08.702Z rhea-promise:translate [connection-1] Translating the context for event: 'accepted'.
2019-06-19T19:43:08.703Z rhea:events [connection-1] Link got event: settled
2019-06-19T19:43:08.703Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' got event: 'settled'. Re-emitting the translated context.
2019-06-19T19:43:08.703Z rhea-promise:translate [connection-1] Translating the context for event: 'settled'.
2019-06-19T19:43:08.703Z rhea-promise:sender [connection-1] sender '570121eb-9cad-d141-9cba-0ed86baa6a61--sender-server' has been closed, now closing it's amqp session 'local-58_remote-58_connection-1'.
2019-06-19T19:43:08.703Z rhea-promise:error [connection-1] The amqp session 'local-58_remote-58_connection-1' is open ? -> true
2019-06-19T19:43:08.703Z rhea-promise:session [connection-1] Calling session.close() for amqp session 'local-58_remote-58_connection-1'.
2019-06-19T19:43:08.703Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object 'local-59_remote-undefined_connection-1' 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.
2019-06-19T19:43:08.706Z rhea-promise:session [connection-1] Calling amqp session.begin().
2019-06-19T19:43:08.706Z rhea:frames [connection-1]:58 -> end#17 {}
2019-06-19T19:43:08.712Z rhea:frames [connection-1]:59 -> begin#11 {"incoming_window":2048,"outgoing_window":4294967295}
2019-06-19T19:43:08.712Z rhea:io [connection-1] read 47 bytes
2019-06-19T19:43:08.712Z rhea:io [connection-1] got frame of size 12
2019-06-19T19:43:08.712Z rhea:frames [connection-1]:58 <- end#17 {}
2019-06-19T19:43:08.713Z rhea:events [connection-1] Session got event: session_close
2019-06-19T19:43:08.713Z rhea-promise:session [connection-1] session 'local-58_remote-58_connection-1' got event: 'session_close'. Re-emitting the translated context.
2019-06-19T19:43:08.713Z rhea-promise:translate [connection-1] Translating the context for event: 'session_close'.
2019-06-19T19:43:08.713Z rhea-promise:session [connection-1] Resolving the promise as the amqp session 'local-58_remote-58_connection-1' has been closed.
2019-06-19T19:43:08.713Z rhea:io [connection-1] got frame of size 35
2019-06-19T19:43:08.713Z rhea:frames [connection-1]:58 <- begin#11 {"remote_channel":59,"incoming_window":2147483647,"outgoing_window":2147483647}
2019-06-19T19:43:08.713Z rhea:events [connection-1] Session got event: session_open
2019-06-19T19:43:08.713Z rhea-promise:session [connection-1] session 'local-59_remote-58_connection-1' got event: 'session_open'. Re-emitting the translated context.
2019-06-19T19:43:08.713Z rhea-promise:translate [connection-1] Translating the context for event: 'session_open'.
2019-06-19T19:43:08.713Z rhea-promise:session [connection-1] Resolving the promise with amqp session 'local-59_remote-58_connection-1'.
2019-06-19T19:43:08.714Z rhea-promise:session [connection-1] Added event handler for event 'session_error' on rhea-promise 'session: local-59_remote-58_connection-1', while creating the sender.
2019-06-19T19:43:08.714Z 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.
2019-06-19T19:43:08.714Z rhea-promise:eventhandler [connection-1] ListenerCount for event 'sender_error' on rhea's 'sender' object is: 1.
2019-06-19T19:43:08.714Z rhea:frames [connection-1]:59 -> attach#12 {"name":"88ea5555-1ce6-fa4b-8cd7-457e49252508--sender-server","source":["hive.guest.events",null,null,null,true],"target":[]}
2019-06-19T19:43:08.714Z rhea:io [connection-1] read 169 bytes
2019-06-19T19:43:08.714Z rhea:io [connection-1] got frame of size 124
2019-06-19T19:43:08.715Z rhea:frames [connection-1]:58 <- attach#12 {"name":"88ea5555-1ce6-fa4b-8cd7-457e49252508--sender-server","role":true,"snd_settle_mode":2,"source":[null,0,null,0,false],"target":[null,0,null,0,false]}
2019-06-19T19:43:08.715Z rhea:events [connection-1] Connection got event: protocol_error
2019-06-19T19:43:08.715Z rhea-promise:connection [connection-1] connection 'connection-1' got event: 'protocol_error'. Re-emitting the translated context.
2019-06-19T19:43:08.715Z rhea-promise:translate [connection-1] Translating the context for event: 'protocol_error'.
2019-06-19T19:43:08.715Z rhea-promise:translate [connection-1] ProtocolError is: { [ProtocolError: attach received on invalid channel 58]
2019-06-19T19:43:08.723Z rhea:reconnect [connection-1] Scheduled reconnect in 100ms
2019-06-19T19:43:08.745Z rhea:events [connection-1] Connection got event: disconnected
2019-06-19T19:43:08.745Z rhea-promise:connection [connection-1] connection 'connection-1' got event: 'disconnected'. Re-emitting the translated context.
2019-06-19T19:43:08.746Z rhea-promise:translate [connection-1] Translating the context for event: 'disconnected'.
2019-06-19T19:43:08.746Z rhea-promise:error [connection-1] Connection got disconnected while closing amqp sender '88ea5555-1ce6-fa4b-8cd7-457e49252508--sender-server' on amqp session 'local-59_remote-58_connection-1': undefined.
2019-06-19T19:43:08.857Z rhea-promise:eventhandler [connection-1] rhea-promise 'session' object 'local-58_remote-undefined_connection-1' 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.
2019-06-19T19:43:08.896Z rhea-promise:session [connection-1] Calling amqp session.begin().
2019-06-19T19:43:08.896Z rhea:reconnect [connection-1] reconnecting...
2019-06-19T19:43:08.907Z rhea:io [connection-1] connected ::1:52386 -> ::1:5672

Also attaching the actual log file for your reference rhea.log

[grs]

@amarzavery thanks! That is indeed a bug. I'll get a fix in next week.

[amarzavery]

Thanks @grs for your prompt response! Thanks @GaikwadPratik for successive test runs to provide updated logs!

[grs]

@GaikwadPratik @amarzavery indeed, thank you both for persisting in tracking this down, much appreciated!

[GaikwadPratik]

@grs , @amarzavery ,
Actually thank you both for helping me out here... I am learning so much about AMQP and how to utilize it better through these two libraries...

[grs]

rhea 1.0.8 should fix the issue

[amarzavery]

Thanks @grs for providing the fix. Will update the min dependency of rhea to the latest version and merge the PR in rhea-promise.

[GaikwadPratik]

@grs ,
Thanks for the fix.

@amarzavery ,
When can I expect next version for rhea-promise to be published? I would like to utilize new changes including async sender and start testing more stuff :)

[amarzavery]

@GaikwadPratik - 1.0.0 version of rhea-promise is available. You can take a look at the AwaitableSender example over here.

[GaikwadPratik]

@amarzavery ,

Thanks a lot for going through all these efforts with @grs and @ramya-rao-a's awesome review... I'll use work with new changes :D