[
https://issues.apache.org/jira/browse/PROTON-2900?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18008057#comment-18008057
]
Marco Geri commented on PROTON-2900:
------------------------------------
After enabling the log level to {{{}TRACE{}}}, I noticed that as soon as the
application starts and begins using ProtonJ2, the first idle check is scheduled
after 10 seconds.
Immediately after, the application opens the connection and receives an
{{idleTimeout}} of 5 seconds from the server. However, the idle check is not
rescheduled accordingly, so it still triggers after 10 seconds.
As a result, the client doesn't detect the server's idle timeout in time, and
Broker-J disconnects the client due to inactivity.
Below is a relevant excerpt from the logs:
2025-07-18 14:11:53 [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] TRACE
org.apache.qpid.protonj2.engine.impl.ProtonEngine - Auto Idle Timeout Check
being initiated
2025-07-18 *14:11:53* [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] TRACE
org.apache.qpid.protonj2.engine.impl.ProtonEngine - IdleTimeoutCheck
rescheduling with delay: *10000*
... (after opening the connection, we receive the AMPQ Open frame response from
BrokerJ)
2025-07-18 *14:11:53* [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] TRACE
org.apache.qpid.protonj2.engine.impl.ProtonFrameLoggingHandler - <-
AMQP:[1160649162:0] Open{ containerId='21a05bf2-0953-4317-9095-d8b77408472a',
hostname='null', maxFrameSize=65536, channelMax=255, idleTimeOut={*}5000{*},
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS,
sole-connection-for-container], desiredCapabilities=null,
properties=\{product=Apache Qpid Broker-J Core, version=9.2.1,
qpid.build=63289b4d1cf001e1fc3d4b0e2e4dce64d8997241, qpid.instance_name=Broker,
qpid.virtualhost_properties_supported=true}}
... (the Idle check runs after 10 seconds, and try to reschedule it considering
the IdleTimeOut received by BrokerJ, but it's too late and BrokerJ disconnects
it for inactivity)
2025-07-18 *14:12:03* [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] TRACE
org.apache.qpid.protonj2.engine.impl.ProtonEngine - IdleTimeoutCheck
rescheduling with delay: *1250*
2025-07-18 14:12:03 [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] TRACE
org.apache.qpid.protonj2.client.transport.netty4.TcpTransport - Transport
indicates connection failure! Channel is [id: 0x1ba3d764, L:/127.0.0.1:41548 !
R:localhost/127.0.0.1:5672]
2025-07-18 *14:12:03* [ClientConnection
:(ID:17d61cf3-2af8-41fa-9ae1-97482ae06863:1:1): I/O Thread] DEBUG
org.apache.qpid.protonj2.client.impl.ClientTransportListener - *Transport
failed: Remote closed connection unexpectedly*
Hope this helps.
> `IdleTimeoutCheck` not rescheduled after broker's AMQP Open frame, causing
> premature connection closure
> -------------------------------------------------------------------------------------------------------
>
> Key: PROTON-2900
> URL: https://issues.apache.org/jira/browse/PROTON-2900
> Project: Qpid Proton
> Issue Type: Bug
> Components: protonj2
> Affects Versions: protonj2-1.0.0-M23
> Reporter: Marco Geri
> Assignee: Timothy A. Bish
> Priority: Major
>
> While testing with BrokerJ 9.2.1 with AMQP 1.0 protocol, I configured the
> broker to request heartbeats every 5 seconds using the setting
> {{{}qpid.port.heartbeatDelay=5{}}}.
> However, even with a simple login test (without sending any other messages),
> the connection is closed by the broker after 10 seconds due to inactivity. It
> appears that the client library does not send any idle (heartbeat) frames
> during this time.
> After a quick debugging session, it seems that the {{IdleTimeoutCheck}} in
> the {{ProtonEngine}} is scheduled immediately with a timeout of 10 seconds,
> before the AMQP Open frame from the broker is received. The Open frame from
> the broker specifies a 5-second idle timeout, but the {{IdleTimeoutCheck}} is
> *not* rescheduled after this frame is processed.
> As a result, the client does not send heartbeat frames within the expected
> timeframe, and the broker closes the connection due to inactivity.
> *Note:* I ran the test using BrokerJ version 9.2.1, which includes a fix for
> the {{heartbeatDelay}} parameter (see QPID-8680).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
