Skip to content
This repository has been archived by the owner on Dec 14, 2020. It is now read-only.

Epoch receivers -- amqp:link:stolen detach error causing close of other link #43

Closed
devigned opened this issue Feb 28, 2018 · 1 comment

Comments

@devigned
Copy link
Contributor

As mentioned in #42, Event Hubs has a feature where a receiver can specify an epoch. The epoch value must be a long (can't be a string, ulong or anything else) set in the attach performative properties.

The behavior of this broker feature is as follows:

  1. if a receiver, r1 is attached with epoch e1, and then subsequently receiver r2 is attached with epoch e2 where e2 > e1, r1 will be detached by the server.
  2. if a receiver, r1 is attached with epoch e1, and then subsequently receiver r2 is attached with epoch e2 where e2 < e1, r2 will not be allowed to attach.

In case 2, using a single connection between r1 and r2, I see both r1 and r2 close. I would expect only r2 to fail to attach and r1 would stay open, not close.

It appears the context for r1 is closed when r2 receives the detach error.

Excerpt from debug output for e1 = 4 and e2 = 1

TX: Begin{RemoteChannel: 0, NextOutgoingID: 0, IncomingWindow: 5000, OutgoingWindow: 4294967295, HandleMax: 0, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[]}
RX: Begin{RemoteChannel: 1, NextOutgoingID: 1, IncomingWindow: 5000, OutgoingWindow: 5000, HandleMax: 255, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[]}
TX: Attach{Name: jgttgCWUNisofYoKKyeAaQcCvlqeprIhIoPOqOYt, Handle: 0, Role: Receiver, SenderSettleMode: unsettled, ReceiverSettleMode: second, Source: source{Address: goehtest-pjkavlk4cq/ConsumerGroups/$Default/Partitions/0, Durable: 0, ExpiryPolicy: , Timeout: 0, Dynamic: false, DynamicNodeProperties: map[], DistributionMode: , Filter: map[apache.org:selector-filter:string:describedType{descriptor: 77567109365764, value: amqp.annotation.x-opt-offset >= '-1'}], DefaultOutcome: <nil>Outcomes: [], Capabilities: []}, Target: <nil>, Unsettled: map[], IncompleteUnsettled: false, InitialDeliveryCount: 0, MaxMessageSize: 9223372036854775807, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[com.microsoft:epoch:4]}
RX(Session): Attach{Name: jgttgCWUNisofYoKKyeAaQcCvlqeprIhIoPOqOYt, Handle: 0, Role: Sender, SenderSettleMode: settled, ReceiverSettleMode: <nil>, Source: source{Address: goehtest-pjkavlk4cq/ConsumerGroups/$Default/Partitions/0, Durable: 0, ExpiryPolicy: session-end, Timeout: 0, Dynamic: false, DynamicNodeProperties: map[], DistributionMode: , Filter: map[apache.org:selector-filter:string:describedType{descriptor: 77567109365764, value: amqp.annotation.x-opt-offset >= '-1'}], DefaultOutcome: <nil>Outcomes: [], Capabilities: []}, Target: <nil>, Unsettled: map[], IncompleteUnsettled: false, InitialDeliveryCount: 0, MaxMessageSize: 266240, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[com.microsoft:epoch:4]}

TX: Begin{RemoteChannel: 0, NextOutgoingID: 0, IncomingWindow: 5000, OutgoingWindow: 4294967295, HandleMax: 0, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[]}
RX: Begin{RemoteChannel: 3, NextOutgoingID: 1, IncomingWindow: 5000, OutgoingWindow: 5000, HandleMax: 255, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[]}
TX: Attach{Name: gCodtOUPdHLKkVwARWZfXPvOfWmzGHPolHezofUZ, Handle: 0, Role: Receiver, SenderSettleMode: unsettled, ReceiverSettleMode: second, Source: source{Address: goehtest-pjkavlk4cq/ConsumerGroups/$Default/Partitions/0, Durable: 0, ExpiryPolicy: , Timeout: 0, Dynamic: false, DynamicNodeProperties: map[], DistributionMode: , Filter: map[apache.org:selector-filter:string:describedType{descriptor: 77567109365764, value: amqp.annotation.x-opt-offset >= '-1'}], DefaultOutcome: <nil>Outcomes: [], Capabilities: []}, Target: <nil>, Unsettled: map[], IncompleteUnsettled: false, InitialDeliveryCount: 0, MaxMessageSize: 9223372036854775807, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[com.microsoft:epoch:1]}
RX(Session): Attach{Name: gCodtOUPdHLKkVwARWZfXPvOfWmzGHPolHezofUZ, Handle: 0, Role: Sender, SenderSettleMode: unsettled, ReceiverSettleMode: second, Source: <nil>, Target: <nil>, Unsettled: map[], IncompleteUnsettled: false, InitialDeliveryCount: 0, MaxMessageSize: 266240, OfferedCapabilities: [], DesiredCapabilities: [], Properties: map[link-name:gCodtOUPdHLKkVwARWZfXPvOfWmzGHPolHezofUZ client-max-frame-size:480 com.microsoft:epoch:1]}
TX(Session): Detach{Handle: 0, Closed: true, Error: *Error(nil)}
TX(Session): Flow{NextIncomingID: 1, IncomingWindow: 5000, NextOutgoingID: 0, OutgoingWindow: 4294967295, Handle: 0, DeliveryCount: 0, LinkCredit: 100, Available: <nil>, Drain: false, Echo: false, Properties: map[]}
ERRO[0041] entity path goehtest-pjkavlk4cq/ConsumerGroups/$Default/Partitions/0 and epoch 4 error: context canceled

RX(Session): Detach{Handle: 0, Closed: true, Error: *Error{Condition: amqp:link:stolen, Description: A receiver with a higher epoch '4' already exists. A new receiver with epoch 1 cannot be created. Make sure you are creating receiver with increasing epoch value to ensure connectivity, or ensure all old epoch receivers are closed or disconnected. TrackingId:8a804a40-52f5-48b3-ada9-08eb219f01b8_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191, Timestamp:2/28/2018 3:41:45 PM Reference:5569318e-5e9b-441a-b780-88b73dcc55b0, TrackingId:2078bf14-76e7-437c-a7fa-4e15e478e0cd_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191|$default, Timestamp:2/28/2018 3:41:45 PM TrackingId:a23d3b1f30694314ba5b70b64ce53de3_G26, SystemTracker:gateway2, Timestamp:2/28/2018 3:41:45 PM, Info: map[]}}
RX: Detach{Handle: 0, Closed: true, Error: *Error{Condition: amqp:link:stolen, Description: A receiver with a higher epoch '4' already exists. A new receiver with epoch 1 cannot be created. Make sure you are creating receiver with increasing epoch value to ensure connectivity, or ensure all old epoch receivers are closed or disconnected. TrackingId:8a804a40-52f5-48b3-ada9-08eb219f01b8_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191, Timestamp:2/28/2018 3:41:45 PM Reference:5569318e-5e9b-441a-b780-88b73dcc55b0, TrackingId:2078bf14-76e7-437c-a7fa-4e15e478e0cd_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191|$default, Timestamp:2/28/2018 3:41:45 PM TrackingId:a23d3b1f30694314ba5b70b64ce53de3_G26, SystemTracker:gateway2, Timestamp:2/28/2018 3:41:45 PM, Info: map[]}}
TX(Session): Detach{Handle: 0, Closed: true, Error: *Error(nil)}
RX(Session): Detach{Handle: 0, Closed: true, Error: *Error(nil)}
ERRO[0041] entity path goehtest-pjkavlk4cq/ConsumerGroups/$Default/Partitions/0 and epoch 1 error: link detached, reason: *Error{Condition: amqp:link:stolen, Description: A receiver with a higher epoch '4' already exists. A new receiver with epoch 1 cannot be created. Make sure you are creating receiver with increasing epoch value to ensure connectivity, or ensure all old epoch receivers are closed or disconnected. TrackingId:8a804a40-52f5-48b3-ada9-08eb219f01b8_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191, Timestamp:2/28/2018 3:41:45 PM Reference:5569318e-5e9b-441a-b780-88b73dcc55b0, TrackingId:2078bf14-76e7-437c-a7fa-4e15e478e0cd_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191|$default, Timestamp:2/28/2018 3:41:45 PM TrackingId:a23d3b1f30694314ba5b70b64ce53de3_G26, SystemTracker:gateway2, Timestamp:2/28/2018 3:41:45 PM, Info: map[]}

RX(Session): Detach{Handle: 0, Closed: true, Error: *Error{Condition: amqp:link:detach-forced, Description: The link 'G26:29035311:opkxrbrNvsKWErgDdrEDiUshYNcwdYkxOzzsFHTg' is force detached by the broker due to errors occurred in publisher(link5075554). Detach origin: Message sender was closed because entity has been deleted.. TrackingId:bf8e03460000a344004d72625a96cdba_G26_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191, Timestamp:2/28/2018 3:41:51 PM, Info: map[]}}
RX: Detach{Handle: 0, Closed: true, Error: *Error{Condition: amqp:link:detach-forced, Description: The link 'G26:29035311:opkxrbrNvsKWErgDdrEDiUshYNcwdYkxOzzsFHTg' is force detached by the broker due to errors occurred in publisher(link5075554). Detach origin: Message sender was closed because entity has been deleted.. TrackingId:bf8e03460000a344004d72625a96cdba_G26_B25, SystemTracker:ehdjtest:eventhub:goehtest-pjkavlk4cq~8191, Timestamp:2/28/2018 3:41:51 PM, Info: map[]}}
TX(Session): Detach{Handle: 0, Closed: true, Error: *Error(nil)}
@devigned
Copy link
Contributor Author

Closing the issue since the bug in the implementation was mine. I was cancelling the context for the original receiver.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant