accept disposition v/s modified (undeliverable_here: true)

amarzavery commented 5 years ago

Logs for accept disposition

1. rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"state":[]}  +11ms
  2. rhea:raw [connection-1] SENT: 28 0000001c02000001005315d00000000c000000054143434200532445 +11ms
  3. rhea:frames [connection-1]:1 -> flow#13 {"next_incoming_id":1,"incoming_window":2047,"outgoing_window":4294967295,"delivery_count":1,"link_credit":1}  +0ms
  4. rhea:raw [connection-1] SENT: 38 0000002602000001005313d00000001600000007520170000007ff4370ffffffff4352015201 +0ms
  5. rhea:io [connection-1] read 23 bytes +123ms
  6. rhea:io [connection-1] got frame of size 23 +0ms
  7. rhea:raw [connection-1] RECV: 23 0000001702000001005315c00a06424340410053244540 +112ms
  8. rhea:frames [connection-1]:1 <- disposition#15 {"settled":true,"state":[]}  +112ms
  9. rhea:events [connection-1] Received disposition for incoming transfers +118ms
  10. rhea:events [connection-1] Link got event: settled +0ms
  11. rhea-promise:receiver [connection-1] receiver got event: 'settled'.

Logs for modified disposition with undeliverable_here set to true

azure:service-bus:servicebusMessage [connection-1] Deferring the message with id '1a40c17c9dee4b68ac6ae3c74d5733f1'. +4ms
  azure:service-bus:concurrentMap Key 'd321216e-4239-6447-a790-0e00c88200cf' is present in the map? -> undefined +0ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"settled":true,"state":[null,true]}  +11ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434341005327d000000006000000024041 +11ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"settled":true,"state":[null,true]}  +0ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434341005327d000000006000000024041 +0ms
  rhea:frames [connection-1]:1 -> flow#13 {"next_incoming_id":1,"incoming_window":2048,"outgoing_window":4294967295,"delivery_count":1,"link_credit":1}  +0ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005313d00000001600000007520170000008004370ffffffff4352015201 +0ms
  azure:service-bus:receiver [connection-1] Disposition for delivery id: 0, did not complete in 20000 milliseconds. Hence resolving the promise. +20s

For modified disposition with undeliverable_here set to true, I see that rhea is sending the disposition twice and settled is already set to true. May be that is why I am not getting a response disposition from ServiceBus. Any idea

why is settled being set to true for modified and not being set at all in accept?
why is the disposition being sent twice for modified v/s only once for accept (I am not calling modified twice from my sdk)?

options being set while creating the receiver link are as follows

const rcvrOptions: ReceiverOptions = {
      name: this.name,
      autoaccept: false,
      rcv_settle_mode: 1,
      snd_settle_mode: 0,
      source: {
        address: this.address
      },
      credit_window: 1
}

As a matter of fact it is behaving in a similar way for modified with undeliverable_here set to false (we call that abandon in ServiceBus terminology)

sending the disposition twice
sending the disposition already settled

  azure:service-bus:servicebusMessage [connection-1] Abandoning the message with id '63e5eec49b5c42919a306f38bd3e92f2'. +3ms
  azure:service-bus:concurrentMap Key '3d2cc395-2d38-ef4a-b568-157e3a2b00c0' is present in the map? -> undefined +0ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"settled":true,"state":[null,false]}  +10ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434341005327d000000006000000024042 +10ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"settled":true,"state":[null,false]}  +0ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434341005327d000000006000000024042 +0ms
  rhea:frames [connection-1]:1 -> flow#13 {"next_incoming_id":1,"incoming_window":2048,"outgoing_window":4294967295,"delivery_count":1,"link_credit":1}  +1ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005313d00000001600000007520170000008004370ffffffff4352015201 +1ms

grs commented 5 years ago

why is settled being set to true for modified and not being set at all in accept?

That is a bug. I'm assuming you are using rcv_settle_mode 1 i.e. second? In that case the sender should settle first and the accept and release methods correctly check the settlement mode. The modified and reject methods however incorrectly assume first as the settlement mode. I've pushed a fix here: https://github.com/amqp/rhea/pull/158

why is the disposition being sent twice for modified v/s only once for accept

Have you turned off auto_accept? Do you have a code snippet that reproduces the double disposition?

amarzavery commented 5 years ago

Options being set on the receiver link are as follows

const rcvrOptions: ReceiverOptions = {
      name: this.name,
      autoaccept: false, // being set to false as you expected.
      rcv_settle_mode: 1, //second
      snd_settle_mode: 0,
      source: {
        address: this.address
      },
      credit_window: 1
};

grs commented 5 years ago

I can't see why it would be sent twice if the delivery is only being updated once (with modified). Are you able to create a simple reproducer?

amarzavery commented 5 years ago

Thanks @grs #158 fixed the settled part. However, it is still sending the disposition twice as you can see in the logs.

  azure:service-bus:servicebusMessage [connection-1] Deferring the message with id '63e5eec49b5c42919a306f38bd3e92f2'. +4ms
  azure:service-bus:concurrentMap Key 'bc849108-6d9e-414c-b994-bfcce92c00c0' is present in the map? -> undefined +0ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"state":[null,true]}  +10ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434342005327d000000006000000024041 +11ms
  rhea:frames [connection-1]:1 -> disposition#15 {"role":true,"state":[null,true]}  +0ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005315d0000000160000000541434342005327d000000006000000024041 +0ms
  rhea:frames [connection-1]:1 -> flow#13 {"next_incoming_id":1,"incoming_window":2047,"outgoing_window":4294967295,"delivery_count":1,"link_credit":1}  +0ms
  rhea:raw [connection-1] SENT: 38 0000002602000001005313d00000001600000007520170000007ff4370ffffffff4352015201 +0ms
  rhea:io [connection-1] read 28 bytes +104ms
  rhea:io [connection-1] got frame of size 28 +0ms
  rhea:raw [connection-1] RECV: 28 0000001c02000001005315c00f0642434041005327c0040340414040 +93ms
  rhea:frames [connection-1]:1 <- disposition#15 {"settled":true,"state":[null,true,null]}  +93ms
  rhea:events [connection-1] Received disposition for incoming transfers +99ms
  rhea:events [connection-1] Link got event: settled +1ms
  rhea-promise:receiver [connection-1] receiver got event: 'settled'. Re-emitting the translated context. +100ms
  rhea-promise:translate [connection-1] Translating the context for event: 'settled'. +100ms
  azure:service-bus:receiver [connection-1] Delivery with id 0, remote_settled: true, remote_state: c { value: [ Typed { type: [Object], value: null }, { [Boolean: true] type: [Object], value: true }, Typed { type: [Object], value: null } ] } has been received. +97ms
  azure:service-bus:receiver [connection-1] Found the delivery with id 0 in the map and cleared the timer. +0ms
  azure:service-bus:receiver [connection-1] Successfully deleted the delivery with id 0 from the map. true +1ms

Working on the simple reproducer that I can share with you.

amarzavery commented 5 years ago

Sent you an email with the reproducer script. Let me know over email if the script worked and if you can see duplicate dispositions in the logs.

grs commented 5 years ago

@amarzavery thanks! I have fixed the issue in https://github.com/amqp/rhea/commit/99f55a20d7fb507e1607826e84502ed24704835d

amqp / rhea

accept disposition v/s modified (undeliverable_here: true) #157