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
