You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@qpid.apache.org by Jakub Scholz <ja...@scholz.cz> on 2015/07/23 23:50:48 UTC
Minor AMQP 1.0 idle timeout issues in C++ broker and client
Hi,
While playing with the AMQP 1.0 implementation in the C++ broker (0.32 &
0.34, both using Proton 0.9), I noticed some interesting points:
1) When tracing is switched on and AMQP 1.0 client connects with enabled
idle timeout, the broker properly logs the empty frames sent/received to
keep the connection alive. However the log file seems to contain empty line
after each received empty frame, e.g.:
2015-07-23 22:58:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 ->
(EMPTY FRAME)
2015-07-23 22:58:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 <-
(EMPTY FRAME)
2015-07-23 22:59:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 ->
(EMPTY FRAME)
2015-07-23 22:59:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 <-
(EMPTY FRAME)
2015-07-23 23:00:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 ->
(EMPTY FRAME)
2015-07-23 23:00:12 [Protocol] trace [qpid.[::1]:20000-[::1]:46303]: 0 <-
(EMPTY FRAME)
The empty line seems to be inserted always only after received empty frame.
The same seems to appear in the Qpid Messaging log as well.
2) When keeping the connection alive, the C++ broker seems to send the
empty frames always after half of the timeout specified when the connection
opened. The only exception is the first heartbeat, which is sent only after
the full timeout interval. In the log bellow, the idle timeout was set to
120 seconds - the broker sent the first after full 120 seconds, but the
subsequent only after 60 seconds:
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
@open(16) [container-id="b8f9f23f-9759-4b80-991b-38d02a57fb91",
idle-time-out=120000, properties={:"qpid.client_process"="qpid-receive",
:"qpid.client_pid"=5029, :"qpid.client_ppid"=26201}]
2015-07-23 23:26:57 [Model] debug qpid.[::1]:20000-[::1]:46436 connection
opened
2015-07-23 23:26:57 [Model] debug Create connection. user:admin@QPID0000
rhost:qpid.[::1]:20000-[::1]:46436
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
@open(16) [container-id="2d4181f7-2c26-4e08-9757-6a45020adf35",
idle-time-out=120000]
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
@begin(17) [next-outgoing-id=0, incoming-window=2147483647,
outgoing-window=0]
2015-07-23 23:26:57 [Model] debug qpid.[::1]:20000-[::1]:46436 session begun
2015-07-23 23:26:57 [Model] trace Mgmt create session. id:0x7f4100040350
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
@begin(17) [remote-channel=0, next-outgoing-id=0,
incoming-window=2147483647, outgoing-window=0]
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
@attach(18)
[name="broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation_0c40f538-5d16-4f82-a092-df1c2eed978e",
handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0,
source=@source(40)
[address="broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation", durable=0,
timeout=0, dynamic=false, capabilities=:queue], target=@target(41)
[address="broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation", durable=0,
timeout=0, dynamic=false], initial-delivery-count=0]
2015-07-23 23:26:57 [Model] trace Mgmt create outgoing.
id:b8f9f23f-9759-4b80-991b-38d02a57fb91,broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation_0c40f538-5d16-4f82-a092-df1c2eed978e
2015-07-23 23:26:57 [Protocol] debug qpid.[::1]:20000-[::1]:46436 link
0x7f4100006940 attached on 0x7f4100040350
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
@attach(18)
[name="broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation_0c40f538-5d16-4f82-a092-df1c2eed978e",
handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0,
source=@source(40)
[address="broadcast.ABCFR_ABCFRALMMACC1.TradeConfirmation", durable=0,
timeout=0, dynamic=false, distribution-mode=:move, capabilities=:queue],
target=@target(41) [durable=0, timeout=0, dynamic=false],
initial-delivery-count=0]
2015-07-23 23:26:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
@flow(19) [next-incoming-id=0, incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0,
link-credit=1000, drain=false]
2015-07-23 23:28:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:28:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
(EMPTY FRAME)
2015-07-23 23:29:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:30:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:30:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
(EMPTY FRAME)
2015-07-23 23:31:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:32:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:32:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
(EMPTY FRAME)
2015-07-23 23:33:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:34:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 ->
(EMPTY FRAME)
2015-07-23 23:34:57 [Protocol] trace [qpid.[::1]:20000-[::1]:46436]: 0 <-
(EMPTY FRAME)
This seems to be a bit strange, as I see no reason for the first heartbeat
to be sent later.
3) Interestingly, the C++ client seems to approach the idle timeout
differently than the C++ broker and sends the empty frames only after the
full interval (as visible in the log above). Maybe it would be easier if
the broker and client approached the idle timeout in the same way.
Obviously, these issues are not critical, they are more or less cosmetic
issues - do you think they are worth entering a JIRAs? I think that at
least the first point should be fixed, but to be honest I have no idea
whether it is an actual issue in the C++ broker / client or in the Proton
library, because I think the log message comes from Proton.
Thanks & Regards
Jakub
Re: Minor AMQP 1.0 idle timeout issues in C++ broker and client
Posted by Jakub Scholz <ja...@scholz.cz>.
Thanks for looking into this. I verified it with fresh build of Proton and
C++ broker and the issues indeed seem to be fixed now.
Jakub
On Tue, Jul 28, 2015 at 1:09 PM, Gordon Sim <gs...@redhat.com> wrote:
> On 07/23/2015 10:50 PM, Jakub Scholz wrote:
>
>> While playing with the AMQP 1.0 implementation in the C++ broker (0.32 &
>> 0.34, both using Proton 0.9), I noticed some interesting points:
>>
>> 1) When tracing is switched on and AMQP 1.0 client connects with enabled
>> idle timeout, the broker properly logs the empty frames sent/received to
>> keep the connection alive. However the log file seems to contain empty
>> line
>> after each received empty frame
>>
>
> I've fixed that: https://issues.apache.org/jira/browse/PROTON-962
>
> 2) When keeping the connection alive, the C++ broker seems to send the
>> empty frames always after half of the timeout specified when the
>> connection
>> opened. The only exception is the first heartbeat, which is sent only
>> after
>> the full timeout interval. In the log bellow, the idle timeout was set to
>> 120 seconds - the broker sent the first after full 120 seconds, but the
>> subsequent only after 60 seconds:
>>
> [...]
>
>> This seems to be a bit strange, as I see no reason for the first heartbeat
>> to be sent later.
>>
>
> In both the broker and the client, qpid-cpp uses a timer task to ensure
> that the tick is invoked on proton periodically. However when the
> connection is opened the timer task is started before all the encoding is
> done. Proton resets the time at which it needs to send a heartbeat after it
> does any output which is after the task has been started. So the first time
> the qpid-cpp timer task invokes the tick, it is a couple of milliseconds
> too early, however it does not then call back to check until the next
> interval.
>
> (The design of proton fits more naturally with an io system where the
> timeouts are managed by the poller, and the max wait time is retrieved from
> proton and continually passed into the poll/select. Unfortunately that
> would be a large and intrusive change for the qpid-cpp io layer, hence the
> use of a periodic timer instead).
>
> I can mitigate this by restarting the timer in qpid-cpp whenever it
> encodes data. this avoids the initial longer gap.
>
> 3) Interestingly, the C++ client seems to approach the idle timeout
>> differently than the C++ broker and sends the empty frames only after the
>> full interval (as visible in the log above). Maybe it would be easier if
>> the broker and client approached the idle timeout in the same way.
>>
>
> The c++ client does do more or less the same thing (allowing for some
> differences in threading). I don't see quite the same thing as you. I do
> see the client occasionally 'missing' a heartbeat which makes it look like
> it is using the longer interval, but for me this seems to be an occasional
> occurrence.
>
> I believe I have fixed these two anomalies:
> https://issues.apache.org/jira/browse/QPID-6661
>
> Obviously, these issues are not critical, they are more or less cosmetic
>> issues - do you think they are worth entering a JIRAs? I think that at
>> least the first point should be fixed, but to be honest I have no idea
>> whether it is an actual issue in the C++ broker / client or in the Proton
>> library, because I think the log message comes from Proton.
>>
>> Thanks & Regards
>> Jakub
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
> For additional commands, e-mail: users-help@qpid.apache.org
>
>
Re: Minor AMQP 1.0 idle timeout issues in C++ broker and client
Posted by Gordon Sim <gs...@redhat.com>.
On 07/23/2015 10:50 PM, Jakub Scholz wrote:
> While playing with the AMQP 1.0 implementation in the C++ broker (0.32 &
> 0.34, both using Proton 0.9), I noticed some interesting points:
>
> 1) When tracing is switched on and AMQP 1.0 client connects with enabled
> idle timeout, the broker properly logs the empty frames sent/received to
> keep the connection alive. However the log file seems to contain empty line
> after each received empty frame
I've fixed that: https://issues.apache.org/jira/browse/PROTON-962
> 2) When keeping the connection alive, the C++ broker seems to send the
> empty frames always after half of the timeout specified when the connection
> opened. The only exception is the first heartbeat, which is sent only after
> the full timeout interval. In the log bellow, the idle timeout was set to
> 120 seconds - the broker sent the first after full 120 seconds, but the
> subsequent only after 60 seconds:
[...]
> This seems to be a bit strange, as I see no reason for the first heartbeat
> to be sent later.
In both the broker and the client, qpid-cpp uses a timer task to ensure
that the tick is invoked on proton periodically. However when the
connection is opened the timer task is started before all the encoding
is done. Proton resets the time at which it needs to send a heartbeat
after it does any output which is after the task has been started. So
the first time the qpid-cpp timer task invokes the tick, it is a couple
of milliseconds too early, however it does not then call back to check
until the next interval.
(The design of proton fits more naturally with an io system where the
timeouts are managed by the poller, and the max wait time is retrieved
from proton and continually passed into the poll/select. Unfortunately
that would be a large and intrusive change for the qpid-cpp io layer,
hence the use of a periodic timer instead).
I can mitigate this by restarting the timer in qpid-cpp whenever it
encodes data. this avoids the initial longer gap.
> 3) Interestingly, the C++ client seems to approach the idle timeout
> differently than the C++ broker and sends the empty frames only after the
> full interval (as visible in the log above). Maybe it would be easier if
> the broker and client approached the idle timeout in the same way.
The c++ client does do more or less the same thing (allowing for some
differences in threading). I don't see quite the same thing as you. I do
see the client occasionally 'missing' a heartbeat which makes it look
like it is using the longer interval, but for me this seems to be an
occasional occurrence.
I believe I have fixed these two anomalies:
https://issues.apache.org/jira/browse/QPID-6661
> Obviously, these issues are not critical, they are more or less cosmetic
> issues - do you think they are worth entering a JIRAs? I think that at
> least the first point should be fixed, but to be honest I have no idea
> whether it is an actual issue in the C++ broker / client or in the Proton
> library, because I think the log message comes from Proton.
>
> Thanks & Regards
> Jakub
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org