[PROTON-2422] Proton will sometimes fail to send empty frame if the idle timeout ratio between peers is greater than 2.

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: proton-c-0.33.0, proton-c-0.35.0
• Fix Version/s: proton-c-0.36.0
• Component/s: cpp-binding, proton-c
• Environment: RHEL 8
• Assignee: Clifford Jansen
• Reporter: Jesse Hulsizer
• Created: 30/Aug/21 23:31
• Updated: 05/Nov/21 09:11
• Resolved: 29/Oct/21 16:07

Description

When a connection is made to a proton listener with both sides having different idle timeout intervals, the epoll_timer can fail to trigger, resulting in no empty frames being sent, and the connection dropped with a 'amqp:resource-limit-exceeded: local-idle-timeout expired' exception.

Instrumentation of the proton library showed that when the an epoll timer deadline was rolled back and the timer resequenced due to the peer idle timeout being shorter than the local, the new timer is pushed on the timer manager heap incorrectly. The timer deadline object should be pushed on the timer heap in order by deadline, by in fact the timer is pushed on the head by timer deadline object address. This causes the invalidated timer to be first on the list, and the proactor timer set incorrectly. When enough time has elapsed, the remote peer will close the connection due to inactivity. Note that if the newly created resequenced timer deadline object has an address lower than the old invalidated timer deadline object, proton will work correctly.

I've attached a reproducer as well as a patch for the instrumentation. Annotated proton logging from the reproducer is below.

This issue does not occur prior to 0.33.0

[builder@SE-RHEL8-ITCM-TEST-01 qpid-proton-idle-timeout-repo $ ] PN_LOG='frame info+' ./a.out 
listening on 9030
# The initial connection
[0x7fdb3c001be0]: SASL:FRAME: -> SASL
[0x7fdb44002620]: SASL:FRAME: <- SASL
[0x7fdb44002620]: SASL:FRAME: -> SASL
[0x7fdb44002620]: AMQP:FRAME:0 -> @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS]]
[0x7fdb3c001be0]: SASL:FRAME: <- SASL
[0x7fdb3c001be0]: AMQP:FRAME:0 <- @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS]]
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb3c008570, deadline 5189836829, proactor_timer* 0x10B9660
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump post
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x00007fdb3c008570, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb3c001be0]: AMQP:FRAME:0 -> @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b"anonymous@SE-RHEL8-ITCM-TEST-01"]
[0x7fdb44002620]: AMQP:FRAME:0 <- @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b"anonymous@SE-RHEL8-ITCM-TEST-01"]
[0x7fdb44002620]: SASL: INFO:Authenticated user: anonymous for anonymous with mechanism ANONYMOUS
[0x7fdb44002620]: AMQP:FRAME:0 -> @sasl-outcome(68) [code=0]
[0x7fdb3c001be0]: AMQP:FRAME:0 <- @sasl-outcome(68) [code=0]
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb3c008570, deadline 5189836829, proactor_timer* 0x10B9660
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x00007fdb3c008570, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb3c001be0]: AMQP:FRAME: -> AMQP
[0x7fdb3c001be0]: AMQP:FRAME:0 -> @open(16) [container-id="cf87e911-f46b-471a-a664-e34de8a57b6b", hostname="127.0.0.1", channel-max=32767, idle-time-out=20000]
[0x7fdb44002620]: AMQP:FRAME: <- AMQP
[0x7fdb44002620]: AMQP:FRAME:0 <- @open(16) [container-id="cf87e911-f46b-471a-a664-e34de8a57b6b", hostname="127.0.0.1", channel-max=32767, idle-time-out=20000]
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb44008fb0, deadline 5189806830, proactor_timer* 0x10B7D30
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump post
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb44008ff0, td->list_deadline=5189806830, td->timer=0x00007fdb44008fb0, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb44002620]: AMQP:FRAME: -> AMQP
[0x7fdb44002620]: AMQP:FRAME:0 -> @open(16) [container-id="6fb1e956-e9ca-4922-95a7-072fc249dc24", channel-max=32767, idle-time-out=5000]
[0x7fdb3c001be0]: AMQP:FRAME: <- AMQP
[0x7fdb3c001be0]: AMQP:FRAME:0 <- @open(16) [container-id="6fb1e956-e9ca-4922-95a7-072fc249dc24", channel-max=32767, idle-time-out=5000]
# Here the client has connected to the listener. The client timeout is 40 seconds, and the listener idle timeout is 10 seconds. The proactor timer for this connection
# is re-sequenced and the new timer deadline object is placed on the heap. This is placed in address order, and not list_deadline order as it should be.
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb3c008570, deadline 5189799330, proactor_timer* 0x10B9660
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x00007fdb3c008570, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump post
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x0000000000000000, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 1: td=0x0167fdb3c00a930, td->list_deadline=5189799330, td->timer=0x00007fdb3c008570, td->resequenced=true
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
# After 10 seconds, the listener server has closed the connection due to inactivity.
[0x7fdb44002620]: AMQP:ERROR:amqp:resource-limit-exceeded local-idle-timeout expired
[0x7fdb44002620]: AMQP:FRAME:0 -> @close(24) [error=@error(29) [condition=:"amqp:resource-limit-exceeded", description="local-idle-timeout expired"]]
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb44008fb0, deadline 5189816830, proactor_timer* 0x10B7D30
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump post
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb44008ff0, td->list_deadline=5189816830, td->timer=0x00007fdb44008fb0, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb44002620]: IO:FRAME: -> EOS
[0x7fdb3c001be0]: AMQP:FRAME:0 <- @close(24) [error=@error(29) [condition=:"amqp:resource-limit-exceeded", description="local-idle-timeout expired"]]
[0x7fdb3c001be0]: IO:FRAME: <- EOS
[0x7fdb3c001be0]: AMQP:FRAME:0 -> (EMPTY FRAME)
[0x7fdb4ca21e20]:EVENT: INFO:In pni_timer_set - timer* 0x7fdb3c008570, deadline 5189809330, proactor_timer* 0x10B9660
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x0000000000000000, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 1: td=0x0167fdb3c00a930, td->list_deadline=5189799330, td->timer=0x00007fdb3c008570, td->resequenced=true
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
[0x7fdb4ca21e20]:EVENT: INFO:Start of timer heap dump post
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 0: td=0x0167fdb3c0085b0, td->list_deadline=5189836829, td->timer=0x0000000000000000, td->resequenced=false
[0x7fdb4ca21e20]:EVENT: INFO:Heap position 1: td=0x0167fdb3c00a930, td->list_deadline=5189799330, td->timer=0x00007fdb3c008570, td->resequenced=true
[0x7fdb4ca21e20]:EVENT: INFO:Stop of timer heap dump
amqp:resource-limit-exceeded: local-idle-timeout expired
amqp:resource-limit-exceeded: local-idle-timeout expired
Sender was disconnected. Test Failed.

 

 

 

Issue Links

• Is contained by: PROTON-1890 [c++] implement idle_timeout and heartbeats
• relates to: PROTON-2411 Simultaneous idle timeout sequencing errors on 32bit system