Downstream heartbeat pump misses timer slots under channel fanout on shared upstream — client-side `MissedHeartbeatException` (downstream analog of #210)

[Akashc080167]

Describe the bug

Terminology used below (all three numbers matter and are easy to conflate):

• heartbeat = 60 s — the interval negotiated in connection.tune (this is what the Java client's log message reports).
• heartbeat/2 = 30 s — the conventional peer send cadence (each side emits one heartbeat frame every 30 s so the far side has a retry chance before its deadline).
• 2 × heartbeat = 120 s — the Java client's MissedHeartbeatException deadline (per com.rabbitmq:amqp-client: two consecutive 60 s socket-read timeouts with no frame received).

On v3.2.0 (which fixed the upstream heartbeat pump per #210), the downstream heartbeat pump still misses timer slots when a single upstream connection multiplexes a large number of downstream channels. Concretely: amq_proxy.client[client: "<ip:port>"] Sending heartbeat (last heartbeat 30s ago) log lines that should appear at ~30 s wall-clock cadence (heartbeat/2 for negotiated heartbeat=60) appear at 60 s, 90 s, 120 s, and occasionally 130–140 s intervals for the same connection. When the gap exceeds the client's 2 × heartbeat = 120 s grace, the AMQP 0-9-1 client library (in our case Java com.rabbitmq:amqp-client) raises MissedHeartbeatException, closes the TCP socket, and the proxy then reads EOF (IO::EOFError: End of file reached) on that downstream socket.

Note: the log message always literally says "last heartbeat 30s ago" — this string appears to be a hard-coded reflection of the configured heartbeat interval, not the actual elapsed time. The delay is invisible in the log message text; only the log timestamps reveal it.

The proxy is not CPU- or memory-constrained when this happens (see setup below — measured usage is ~3–4 mCPU and ~4–5 MiB per pod). This looks like fiber scheduling latency inside the single-threaded Crystal reactor when one fiber has to walk many downstream sockets on each heartbeat tick.

Describe your setup

• amqproxy: v3.2.0 (2026-08-31 release), cloudamqp/amqproxy:v3.2.0 (linux/amd64)
• Deployment: 3 replicas on GKE (Kubernetes 1.34), Guaranteed QoS pods, no cgroup pressure
• Container args: amqproxy --listen=0.0.0.0 --debug --idle-connection-timeout=120 amqps://<broker>:5671
• --max-upstream-channels: not set (default — server max or 65535), so one upstream connection accumulates 150–200+ downstream channels at steady state
• Upstream: in-cluster self-hosted RabbitMQ 4.3.4 on Erlang 27.3.4.15, 3-node cluster, healthy (5% CPU, 0.2 GB / 3.0 GB memory watermark)
• Downstream clients: ~15 Spring AMQP services (Java com.rabbitmq:amqp-client), default requested-heartbeat=60, each with a SimpleMessageListenerContainer opening 5–15 channels
• Steady-state channel fanout: ~180 downstream channels multiplexed onto one upstream AMQPS connection
• Per-proxy-pod resource usage: 3–4 mCPU, 4–5 MiB (essentially idle — nowhere near any cgroup limit)
• Network path: pure Kubernetes CNI, pod-to-pod, no LB / NAT / firewall between client pods and proxy pods (confirmed via nf_conntrack_tcp_timeout_established = 86400; no session-tracking middlebox exists on this leg)

How to reproduce

1. Deploy amqproxy v3.2.0 as a K8s Deployment, args ["--listen=0.0.0.0", "--debug", "amqps://<broker>:5671"].
2. Point ~15 Spring AMQP services (default heartbeat=60) at it, each opening 5–15 channels via SimpleMessageListenerContainer.
3. Wait until aggregate channel count on any one upstream connection exceeds ~150 (visible on the broker side via rabbitmqctl list_connections peer_host channels).
4. Observe on client side: com.rabbitmq.client.MissedHeartbeatException: Heartbeat missing with heartbeat = 60 seconds at a steady ~3–7/min rate across the client fleet.
5. In amqproxy debug logs, grep for IO::EOFError — steady rate of ~3–7/min matches, one line per client that timed out.
6. For any one such disconnect, grep the proxy debug log for that client's <ip:port> and look at the wall-clock intervals between successive Sending heartbeat (last heartbeat 30s ago) lines: intervals should be 30 s but are frequently 60–120+ s.

Anchor evidence — two client connections on two different proxy pods, same downstream client service

Connection A (client 100.76.0.166:59822, proxy pod A):

2026-09-06T07:02:42.234891Z  Connected
2026-09-06T07:03:12.433230Z  Sending heartbeat (last heartbeat 30s ago)      Δ=30.198s  ✓
2026-09-06T07:05:27.535556Z  Disconnected #<IO::EOFError:End of file reached>
                              ^^ 135.10 s of ZERO heartbeat frames — client's 120 s grace expired

Connection B (client 100.76.0.166:47448, proxy pod B):

2026-09-06T06:56:13.897321Z  Connected
2026-09-06T06:56:43.900677Z  Sending heartbeat (last heartbeat 30s ago)      Δ=30.003s   ✓
2026-09-06T06:58:13.897704Z  Sending heartbeat (last heartbeat 30s ago)      Δ=89.997s   ❌ (2 slots skipped)
2026-09-06T07:00:13.897320Z  Sending heartbeat (last heartbeat 30s ago)      Δ=120.000s  ❌ (3 slots skipped)
2026-09-06T07:02:13.897380Z  Sending heartbeat (last heartbeat 30s ago)      Δ=120.000s  ❌ (3 slots skipped)
2026-09-06T07:03:13.897309Z  Sending heartbeat (last heartbeat 30s ago)      Δ=60.000s   ❌ (1 slot skipped)
2026-09-06T07:05:29.006527Z  Disconnected #<IO::EOFError:End of file reached>
                              ^^ 135.11 s of silence → client MissedHeartbeatException → EOF

Client-side (Java com.rabbitmq:amqp-client) stack trace matching Connection B's disconnect:

com.rabbitmq.client.ShutdownSignalException: connection error
  at com.rabbitmq.client.impl.AMQConnection.startShutdown(AMQConnection.java:1007)
  at com.rabbitmq.client.impl.AMQConnection.shutdown(AMQConnection.java:997)
  at com.rabbitmq.client.impl.AMQConnection.handleFailure(AMQConnection.java:801)
  at com.rabbitmq.client.impl.AMQConnection.access$500(AMQConnection.java:48)
  at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:696)
Caused by: com.rabbitmq.client.MissedHeartbeatException: Heartbeat missing with heartbeat = 60 seconds
  at com.rabbitmq.client.impl.AMQConnection.handleSocketTimeout(AMQConnection.java:869)
  at com.rabbitmq.client.impl.AMQConnection.readFrame(AMQConnection.java:769)

Aggregate signal (across 3 proxy pods, 60 min sample)

• IO::EOFError disconnect rate: ~4/min steady-state (3–7/min per pod), NOT bursty — matches per-connection heartbeat-slot-miss cadence, not fanout-storm bursts.
• Distribution across 15 distinct client pod IPs — systemic pump problem, not one bad-actor client.
• Top offender: single client pod with 54 events/hr — a Spring service with the highest per-JVM channel count.

Expected behavior

• The proxy should send heartbeat frames to each downstream client at heartbeat/2 (~30 s for default heartbeat=60) with sub-second jitter regardless of how many channels are multiplexed on the shared upstream connection.
• No downstream client should observe > 60 s between heartbeat frames while the proxy has CPU/memory headroom.

Suspected root cause (informational — from reading behavior, not code)

• amqproxy's single-fiber-per-upstream-connection reactor pattern requires that same fiber to walk every downstream socket on each heartbeat tick.
• Under 150–200 downstream channels per upstream, the fiber cannot service the heartbeat timer for every downstream socket within the 120 s AMQP grace window.
• This appears to be the downstream-leg analog of Getting a lot of Upstream error messages #210: Getting a lot of Upstream error messages #210 fixed the upstream leg by making the proxy actively emit heartbeats rather than passively echo them. On the downstream leg the active pump exists (the log lines prove it), but its scheduling cadence degrades under fanout.

Suggested fix directions (informational)

• Decouple each downstream heartbeat pump from the upstream fiber (dedicated timer fiber per downstream connection) so a single busy fiber can't starve peer heartbeat emission across many sockets.
• Or, expose a config knob (e.g. --downstream-heartbeat-cadence-seconds) so operators can tune the pump to fire faster than heartbeat/2 (e.g. every 10 s for a 60 s heartbeat), giving substantial slack for scheduler jitter.
• Or, distribute downstream sockets across multiple Crystal fibers under -Dpreview_mt.
• As a stopgap, update the Sending heartbeat (last heartbeat 30s ago) log message to report the actual elapsed time from the previous emission so scheduler drift becomes visible without cross-referencing timestamps.

Impact / workaround

• Client-side MissedHeartbeatException log noise at a steady rate; the Java client auto-reconnects, so under normal load there is no queue backlog or message loss.
• However, when the broker is restarted, the reconnect storm combined with continued heartbeat misses can exhaust Spring AMQP's declarationRetries × recoveryInterval window on some listeners, leaving them in stopped state until app pod restart — an operational cost.
• Workaround adopted: for high-fanout Spring services, bypass amqproxy and connect the Java client directly to the RabbitMQ cluster. Zero MissedHeartbeatException observed on those services over 2 days post-cutover, matching a peer namespace that has always used direct connect.

References

• Related upstream fix on the other leg: Getting a lot of Upstream error messages #210 (v3.2.0, 2026-08-31) — "Send heartbeats to upstream when the connection is idle"
• Related channel-drift fixes we already benefit from: Close downstream connections when upstream connection closes. #220 (v3.0.2), adding max channels per upstream connection as configurable item #227 & Fix duplicate channel.close frames when client crashes #234 (v3.1.0)

Thanks for maintaining amqproxy — happy to run more diagnostics (proxy debug tails, broker list_connections samples, or a smaller reproducer) if it helps narrow this down.