[
https://issues.apache.org/jira/browse/ARTEMIS-1976?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16539775#comment-16539775
]
Oleg Sushchenko commented on ARTEMIS-1976:
------------------------------------------
Please, provide more information how it works and what I should see in logs.
My steps:
I configured broker.xml by adding this value:
{code}<acceptor
name="amqp">tcp://0.0.0.0:5672?amqpIdleTimeout=10000;tcpSendBufferSize=1048576;tcpReceiveBufferSize=1048576;protocols=AMQP;useEpoll=true;amqpCredits=1000;amqpLowCredits=300</acceptor>
{code}
start a client (java/python - behaviour the same):
{code}python receiver.py --conn-heartbeat 3 --broker-url
localhost:5672/examples --timeout 3000{code}
(you can use https://pypi.python.org/pypi/cli-proton-python client for trying)
and get this log:
{code:java}
[0x220df00]: -> SASL
[0x220df00]: <- SASL
[0x220df00]:0 <- @sasl-mechanisms(64)
[sasl-server-mechanisms=@PN_SYMBOL[:PLAIN, :ANONYMOUS]]
[0x220df00]:0 ->
@sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b"anonymous@dhcp"]
[0x220df00]:0 <- @sasl-outcome(68) [code=0]
[0x220df00]: <- AMQP
[0x220df00]: -> AMQP
[0x220df00]:0 -> @open(16)
[container-id="a7752400-0758-4db0-b619-740569e63941", hostname="localhost",
channel-max=32767, idle-time-out=1500]
[0x220df00]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=2147483647,
outgoing-window=2147483647]
[0x220df00]:0 -> @attach(18)
[name="a7752400-0758-4db0-b619-740569e63941-examples", handle=0, role=true,
snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="exa
mples", durable=0, timeout=0, dynamic=false], target=@target(41) [durable=0,
timeout=0, dynamic=false], initial-delivery-count=0, max-message-size=0]
[0x220df00]:0 -> @flow(19) [incoming-window=2147483647,
next-outgoing-id=0, outgoing-window=2147483647, handle=0, delivery-count=0,
link-credit=10, drain=false]
[0x220df00]:0 <- @open(16) [container-id="my-broker-2.6.2",
max-frame-size=131072, channel-max=65535, idle-time-out=30000,
offered-capabilities=@PN_SYMBOL[:"sole-connection-for-container",
:"DELAYED_DELIVERY", :"SHARED-SUBS", :"ANONYMOUS-RELAY"],
properties={:product="apache-activemq-artemis", :version="2.6.2"}]
[0x220df00]:0 <- @begin(17) [remote-channel=0, next-outgoing-id=1,
incoming-window=2147483647, outgoing-window=2147483647, handle-max=65535]
[0x220df00]:0 <- @attach(18)
[name="a7752400-0758-4db0-b619-740569e63941-examples", handle=0, role=false,
snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="ex
amples"], target=@target(41) [], incomplete-unsettled=false,
initial-delivery-count=0]
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 -> (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 <- (EMPTY FRAME)
[0x220df00]:0 -> (EMPTY FRAME)
{code}
Client sends empty frames every (around) 1 second, but I expect that it will
send it every 5 seconds (as configured in broker.xml.
broker side:
{code}2018-07-11 10:08:47,608 FINE [proton.trace] IN: CH[0] : Empty Frame
2018-07-11 10:08:51,937 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:08:56,938 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:08:58,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on DLQ
2018-07-11 10:08:58,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on DLQ done
2018-07-11 10:08:58,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on examples
2018-07-11 10:08:58,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on examples done
2018-07-11 10:09:01,938 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:02,607 FINE [proton.trace] IN: CH[0] : Empty Frame
2018-07-11 10:09:06,938 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on file:/opt/my
-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:11,939 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on file:/opt/my
-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:16,939 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:17,608 FINE [proton.trace] IN: CH[0] : Empty Frame
2018-07-11 10:09:21,939 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:26,939 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:28,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on DLQ
2018-07-11 10:09:28,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on DLQ done
2018-07-11 10:09:28,051 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on examples
2018-07-11 10:09:28,052 DEBUG
[org.apache.activemq.artemis.core.server.impl.QueueImpl] Scanning for expires
on examples done
2018-07-11 10:09:31,940 DEBUG
[org.apache.activemq.artemis.core.server.reload.ReloadManagerImpl] Validating
lastModified 1531296434000 modified = 1531296434000 on
file:/opt/my-broker-2.6.2/etc//broker.xml
2018-07-11 10:09:32,608 FINE [proton.trace] IN: CH[0] : Empty Frame {code}
Empty frames received every 15 seconds. It doesn't matter which heartbeat I set
on client and which idle timeout I set in broker.xml - broker logs are the same
every time.
If I connect via consumer
{code}artemis consumer --protocol amqp{code}
I get this logs on consumer side:
{code}2018-07-11 10:12:26,122 FINE [proton.trace] IN: CH[1] :
Flow{nextIncomingId=1, incomingWindow=2147483647, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=6000, linkCredit=0,
available=null, drain=true, echo=false, properties=null}
[2095109766:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=6000,
linkCredit=0, available=null, drain=true, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=6000, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=6000, linkCredit=1000,
available=null, drain=true, echo=false, properties=null}
2018-07-11 10:12:29,134 FINE [proton.trace] IN: CH[1] : Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=2147483647,
handle=0, deliveryCount=7000, linkCredit=0, available=null, drain=true,
echo=false, properties=null}
[2095109766:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=7000,
linkCredit=0, available=null, drain=true, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=7000, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=7000, linkCredit=1000,
available=null, drain=true, echo=false, properties=null}
2018-07-11 10:12:32,145 FINE [proton.trace] IN: CH[1] : Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=2147483647,
handle=0, deliveryCount=8000, linkCredit=0, available=null, drain=true,
echo=false, properties=null}
[2095109766:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=8000,
linkCredit=0, available=null, drain=true, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=8000, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=8000, linkCredit=1000,
available=null, drain=true, echo=false, properties=null}
2018-07-11 10:12:35,158 FINE [proton.trace] IN: CH[1] : Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=2147483647,
handle=0, deliveryCount=9000, linkCredit=0, available=null, drain=true,
echo=false, properties=null}
[2095109766:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=9000,
linkCredit=0, available=null, drain=true, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=9000, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=9000, linkCredit=1000,
available=null, drain=true, echo=false, properties=null}
2018-07-11 10:12:38,166 FINE [proton.trace] IN: CH[1] : Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=2147483647,
handle=0, deliveryCount=10000, linkCredit=0, available=null, drain=true,
echo=false, properties=null}
[2095109766:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=10000,
linkCredit=0, available=null, drain=true, echo=false, properties=null}
[2095109766:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=0, deliveryCount=10000, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}{code}
It receives packages every 3 seconds and this time doesn't change when I change
idle timeout in broker.xml
> AMQP IdleTimeout ignoring user defined value
> --------------------------------------------
>
> Key: ARTEMIS-1976
> URL: https://issues.apache.org/jira/browse/ARTEMIS-1976
> Project: ActiveMQ Artemis
> Issue Type: Bug
> Reporter: Oleg Sushchenko
> Priority: Major
>
> Steps:
> * configure broker.xml with amqpIdleTimeout=4000 value:
> {code:java}
> <acceptor
> name="amqp">tcp://0.0.0.0:5672?amqpIdleTimeout=4000;tcpSendBufferSize=1048576;tcpReceiveBufferSize=1048576;protocols=AMQP;useEpoll=true;amqpCredits=1000;amqpLowCredits=300</acceptor>
> {code}
>
> * start broker
> * connect to broker with client
> * check broker logs
> Expected result:
> * I get Empty Frames every 2 seconds
> Actual results:
> * Seems that value is not working because I get an Empty Frame every 15
> seconds
> {code:java}
> 2018-07-10 10:08:29,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:08:44,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:08:59,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:09:14,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:09:29,283 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:09:44,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> 2018-07-10 10:09:59,282 FINE [proton.trace] IN: CH[0] : Empty Frame
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
