[ 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: dev-unsubscr...@qpid.apache.org For additional commands, e-mail: dev-h...@qpid.apache.org