Local stick-table handover aborts after five seconds while progressing · Issue #3521 · haproxy/haproxy · GitHub
Skip to content

Local stick-table handover aborts after five seconds while progressing #3521

Open

Description

@brenc

Detailed Description of the Problem

A soft reload can repeatedly abort the local stick-table handover when a valid transfer takes longer than the peer frontend's hardcoded five-second stream timeout. The new worker keeps only the prefix received before each disconnect, reports a local resync abort, and retries instead of completing one coherent handover.

This is reproducible on unmodified HAProxy 3.4.6 with one local peer, one table, plain loopback TCP, and no remote peers. The same five-second client/server timeouts remain in current master in peers_setup_frontend().

The reproducer routes only the old-worker-to-new-worker handover through a paced loopback relay. With 100,000 entries and the script's default 30-second limit, stock 3.4.6 terminates the first session at approximately five seconds and never completes:

complete=false entries=44312 seconds=30.02 flags=0x10400004

0x10400004 contains the local assignment and local abort diagnostic flags. A peer trace on the teaching worker shows full/partial resync finished immediately after it queues the lesson, followed by peer session released five seconds later while the learner is still draining the transfer.

As a control, changing the internal peer stream timeout from 5 seconds to 60 seconds completes the identical paced transfer:

complete=true entries=100000 seconds=12.60 flags=0x11000003

Expected Behavior

A valid local handover should remain connected long enough to transfer the complete table, or its timeout should be refreshed or bounded according to handover progress rather than terminating an otherwise progressing transfer after five seconds.

Steps to Reproduce the Behavior

  1. Save the script below as repro.py.
  2. Run python3 repro.py /path/to/haproxy-3.4.6.
  3. Observe complete=false, an incomplete entry count, and flags containing the local abort diagnostic bit.
Standalone reproducer
#!/usr/bin/env python3
"""Test a paced stick-table handover between old and new local workers.

The test uses one HAProxy master, loopback sockets, and documentation-only IPv6
keys. It rewrites the configuration before a soft reload so the old worker's
connection to the new worker passes through a deliberately slow TCP relay.
This makes transfers exceed HAProxy's historical five-second peer stream
timeout using only loopback sockets.
"""

import argparse
import os
from pathlib import Path
import re
import signal
import socket
import subprocess
import tempfile
import threading
import time


def command(path: Path, request: str) -> str:
    """Send a runtime command and return its response.

    Args:
        path: Unix socket accepting the command.
        request: HAProxy Runtime API command without its trailing newline.

    Returns:
        The complete decoded response.

    Raises:
        OSError: The socket cannot be reached or read.
    """
    with socket.socket(socket.AF_UNIX) as client:
        client.settimeout(10)
        client.connect(str(path))
        client.sendall((request + "\n").encode())
        chunks: list[bytes] = []
        while chunk := client.recv(65536):
            chunks.append(chunk)
        return b"".join(chunks).decode()


def listener() -> socket.socket:
    """Return a listening socket bound to an available loopback TCP port."""
    server = socket.socket()
    server.bind(("127.0.0.1", 0))
    server.listen()
    return server


def key(index: int) -> str:
    """Return a unique documentation-only IPv6 address for index."""
    return f"2001:db8::{index >> 16:x}:{index & 65535:x}"


class Relay:
    """Forward TCP connections while pacing each direction independently."""

    def __init__(self, server: socket.socket, destination: int, delay: float):
        """Start a relay from server to destination.

        Args:
            server: Bound listener owned by the relay.
            destination: Loopback TCP port receiving forwarded connections.
            delay: Seconds to wait after forwarding each 1 KiB chunk.
        """
        self.server = server
        self.destination = destination
        self.delay = delay
        self.stopped = threading.Event()
        self.lock = threading.Lock()
        self.sockets: set[socket.socket] = set()
        self.workers: list[threading.Thread] = []
        self.thread = threading.Thread(target=self._accept, daemon=True)
        self.thread.start()

    def _accept(self) -> None:
        """Accept connections and start workers for both directions."""
        self.server.settimeout(0.2)
        while not self.stopped.is_set():
            try:
                client, _ = self.server.accept()
            except TimeoutError:
                continue
            except OSError:
                break
            try:
                remote = socket.create_connection(
                    ("127.0.0.1", self.destination), timeout=1,
                )
                remote.settimeout(None)
            except OSError:
                client.close()
                continue
            with self.lock:
                self.sockets.update((client, remote))
            for source, target in ((client, remote), (remote, client)):
                worker = threading.Thread(
                    target=self._forward,
                    args=(source, target),
                    daemon=True,
                )
                self.workers.append(worker)
                worker.start()

    def _forward(self, source: socket.socket, target: socket.socket) -> None:
        """Copy paced chunks until either endpoint closes or the relay stops."""
        try:
            while not self.stopped.is_set():
                chunk = source.recv(1024)
                if not chunk:
                    break
                target.sendall(chunk)
                self.stopped.wait(self.delay)
        except OSError:
            pass
        finally:
            for connection in (source, target):
                try:
                    connection.shutdown(socket.SHUT_RDWR)
                except OSError:
                    pass
                connection.close()
                with self.lock:
                    self.sockets.discard(connection)

    def close(self) -> None:
        """Stop forwarding and close all relay-owned sockets."""
        self.stopped.set()
        self.server.close()
        self.thread.join(timeout=2)
        with self.lock:
            connections = list(self.sockets)
        for connection in connections:
            try:
                connection.shutdown(socket.SHUT_RDWR)
            except OSError:
                pass
            connection.close()
        for worker in self.workers:
            worker.join(timeout=2)


def write_config(
    path: Path,
    admin: Path,
    peer_port: int,
    entries: int,
    threads: int,
    incoming_tls: str = "",
    outgoing_tls: str = "",
    transport: tuple[int, int] | None = None,
) -> None:
    """Write the initial or reload configuration.

    Args:
        path: Destination configuration path.
        admin: Runtime API socket path.
        peer_port: Local peer listener address.
        entries: Stick-table entries required by the test.
        threads: Worker thread count.
        incoming_tls: Optional TLS arguments for the peer listener.
        outgoing_tls: Optional TLS arguments for the local peer server.
        transport: Optional old-listener and relay-destination port pair.
    """
    config = f"""global
  localpeer lab
  nbthread {threads}
  stats socket {admin} level admin
peers synced
  bind 127.0.0.1:{peer_port}{incoming_tls}
  server lab{outgoing_tls}
  table marker type ipv6 size {entries + 100} expire 1h store gpt(1)
"""
    if transport:
        old_port, relay_port = transport
        config += f"""listen handover-transport
  mode tcp
  bind 127.0.0.1:{old_port}
  timeout connect 1s
  timeout client 1m
  timeout server 1m
  server paced 127.0.0.1:{relay_port}
"""
    path.write_text(config)


def wait_for_ready(admin: Path, process: subprocess.Popen[str]) -> int:
    """Wait for initial peer synchronization and return the worker PID."""
    deadline = time.monotonic() + 15
    while time.monotonic() < deadline:
        if process.poll() is not None:
            raise RuntimeError("HAProxy exited before becoming ready")
        try:
            peers = command(admin, "show peers")
            info = command(admin, "show info")
        except OSError:
            time.sleep(0.05)
            continue
        flags = re.search(r"disabled=0 flags=(0x[0-9a-f]+)", peers)
        pid = re.search(r"^Pid: (\d+)", info, re.MULTILINE)
        if flags and int(flags[1], 16) & 3 == 3 and pid:
            return int(pid[1])
        time.sleep(0.05)
    raise RuntimeError("HAProxy did not finish initial peer synchronization")


def seed(admin: Path, entries: int) -> None:
    """Insert entries documentation-only markers into the local table."""
    for offset in range(0, entries, 100):
        request = ";".join(
            f"set table synced/marker key {key(index)} data.gpt[0] 93"
            for index in range(offset, min(offset + 100, entries))
        )
        reply = command(admin, request)
        if reply.strip():
            raise RuntimeError(f"Cannot seed stick table: {reply[:200]}")


def table_count(admin: Path) -> int:
    """Return the number of entries in the synthetic table."""
    output = command(admin, "show table")
    match = re.search(r"# table: synced/marker,.*used:(\d+)", output)
    if not match:
        raise RuntimeError(f"Synthetic table is missing: {output}")
    return int(match[1])


def check(binary: Path, entries: int, threads: int, delay: float,
          timeout: float, tls: bool) -> bool:
    """Run one paced local handover and return whether it completes.

    Args:
        binary: HAProxy executable under test.
        entries: Number of synthetic entries to transfer.
        threads: Worker thread count.
        delay: Relay delay after each 1 KiB chunk.
        timeout: Maximum seconds allowed for the handover.
        tls: Whether to encrypt and mutually authenticate the peer stream.

    Returns:
        True when all entries arrive and synchronization finishes.
    """
    with tempfile.TemporaryDirectory(prefix="ha-local-handover-") as directory:
        root = Path(directory)
        admin = root / "admin.sock"
        config = root / "haproxy.cfg"
        old_listener = listener()
        old_port = int(old_listener.getsockname()[1])
        old_listener.close()
        incoming_tls = outgoing_tls = ""
        if tls:
            key_path = root / "key.pem"
            certificate_path = root / "certificate.pem"
            bundle_path = root / "peer.pem"
            subprocess.run(
                [
                    "openssl", "req", "-x509", "-newkey", "rsa:2048", "-nodes",
                    "-keyout", str(key_path), "-out", str(certificate_path),
                    "-days", "1", "-subj", "/CN=lab",
                ],
                check=True,
                capture_output=True,
            )
            bundle_path.write_bytes(
                certificate_path.read_bytes() + key_path.read_bytes(),
            )
            incoming_tls = (
                f" ssl crt {bundle_path} verify required "
                f"ca-file {certificate_path}"
            )
            outgoing_tls = (
                f" ssl verify required ca-file {certificate_path} "
                f"crt {bundle_path}"
            )
        write_config(
            config,
            admin,
            old_port,
            entries,
            threads,
            incoming_tls,
            outgoing_tls,
        )
        log_path = root / "haproxy.log"
        with log_path.open("w") as log:
            process = subprocess.Popen(
                [str(binary), "-W", "-db", "-f", str(config)],
                stdout=log,
                stderr=log,
                text=True,
                start_new_session=True,
            )
        relay: Relay | None = None
        try:
            old_pid = wait_for_ready(admin, process)
            seed(admin, entries)
            if table_count(admin) != entries:
                raise RuntimeError("Source table was not fully seeded")

            new_listener = listener()
            new_port = int(new_listener.getsockname()[1])
            new_listener.close()
            relay_listener = listener()
            relay_port = int(relay_listener.getsockname()[1])
            relay = Relay(relay_listener, new_port, delay)
            write_config(
                config,
                admin,
                new_port,
                entries,
                threads,
                incoming_tls,
                outgoing_tls,
                (old_port, relay_port),
            )

            os.kill(process.pid, signal.SIGUSR2)
            started = time.monotonic()
            while time.monotonic() - started < 15:
                try:
                    info = command(admin, "show info")
                    pid = re.search(r"^Pid: (\d+)", info, re.MULTILINE)
                    if pid and int(pid[1]) != old_pid:
                        break
                except OSError:
                    pass
                time.sleep(0.05)
            else:
                raise RuntimeError("Reloaded worker did not become ready")

            last_count = 0
            last_flags = "missing"
            while time.monotonic() - started < timeout:
                last_count = table_count(admin)
                peers = command(admin, "show peers")
                flags = re.search(r"disabled=0 flags=(0x[0-9a-f]+)", peers)
                last_flags = flags[1] if flags else "missing"
                if (last_count == entries and flags and
                        int(last_flags, 16) & 3 == 3):
                    elapsed = time.monotonic() - started
                    print(
                        f"complete=true entries={last_count} "
                        f"seconds={elapsed:.2f} flags={last_flags}",
                    )
                    return True
                time.sleep(0.25)
            print(
                f"complete=false entries={last_count} "
                f"seconds={time.monotonic() - started:.2f} "
                f"flags={last_flags}",
            )
            return False
        finally:
            if relay:
                relay.close()
            if process.poll() is None:
                os.killpg(process.pid, signal.SIGTERM)
                process.wait(timeout=10)


def main() -> None:
    """Parse arguments and exit nonzero when local handover fails."""
    parser = argparse.ArgumentParser(description=__doc__)
    parser.add_argument("binary", type=Path)
    parser.add_argument("--entries", type=int, default=100_000)
    parser.add_argument("--threads", type=int, default=8)
    parser.add_argument("--delay", type=float, default=0.005)
    parser.add_argument("--timeout", type=float, default=30)
    parser.add_argument("--tls", action="store_true")
    args = parser.parse_args()
    if args.entries < 1 or args.threads < 1:
        parser.error("entries and threads must be positive")
    if args.delay < 0 or args.timeout <= 0:
        parser.error("delay must be nonnegative and timeout must be positive")
    passed = check(
        args.binary.resolve(),
        args.entries,
        args.threads,
        args.delay,
        args.timeout,
        args.tls,
    )
    raise SystemExit(0 if passed else 1)


if __name__ == "__main__":
    main()

Do you have any idea what may have caused this?

peers_setup_frontend() assigns five-second client and server timeouts to the internal peer frontend and enables PR_O2_INDEPSTR. During a large local handover, the old worker can queue the entire lesson into the socket before the new worker has consumed it. At 4.5 seconds in the reproducer, the old worker had sent 3.8 MB, the socket was healthy, no write timeout was armed, and both read deadlines were about to expire. The teacher's applet-side deadline is not refreshed by its own outbound data, and once the lesson is queued the applet produces nothing more, so nothing refreshes it.

Two details make the local path strictly worse than the remote one in #3518. Because the streams are independent, sc_ep_report_send_activity() does not report read activity, so the teacher's sending never refreshes its read deadline, and the applet-side stream-connector deadline (scf->ioto, 5 s from the frontend client timeout) is refreshed only by applet output, so incoming heartbeats cannot refresh it either; only the connection side sees them. And the learner sends nothing at all during the lesson: it does not advance st->last_get while learnstate == PEER_LR_ST_PROCESSING (line 1829 in 3.4.6), so no acks, and __process_running_peer_sync() only schedules heartbeats inside its !peer->local branch, so no heartbeats either. Any local lesson that takes more than five seconds therefore cannot complete.

The trace reports full/partial resync finished when the lesson has been queued by the applet, not when the learner has received it. Five seconds later the read timeout closes the still-valid session. Raising the timeout to 60 seconds proved the cause but only moved the size/speed threshold, so I discarded that approach.

Do you have an idea how to solve the issue?

This candidate makes the local teaching phase progress-aware while retaining the five-second connection-side timeout. The local learner sends the existing peer heartbeat every three seconds while it is actually processing handover messages. The local teacher sets its applet-side stream-connector timeout (scf->ioto) to eternity for the lesson, because with independent streams that deadline is refreshed only by applet output and the teacher produces nothing after queuing the lesson. The connection-side 5 s read timeout stays armed and is refreshed by the heartbeat bytes. If the learner stops making progress, it sends no heartbeat and the connection still aborts after five seconds.

The diff is against unmodified 3.4.6 and is independent of #3517 to #3520.

Experimental patch
--- a/src/peers.c
+++ b/src/peers.c
@@ -3019,9 +3019,16 @@
         peer->flags &= ~PEER_TEACH_FLAGS;
 
 	if (peer->local && !(appctx_is_back(peer->appctx))) {
+		struct stream *strm = appctx_strm(peer->appctx);
+
 		/* If the local peer has established the connection (appctx is
 		 * on the frontend side), flag it to start to teach lesson.
+		 * With independent streams the applet-side deadline is refreshed
+		 * only by applet output, and the teacher produces nothing once
+		 * the lesson is queued, so only the connection-side read timeout
+		 * can guard this phase.
 		 */
+		strm->scf->ioto = TICK_ETERNITY;
                 peer->flags |= PEER_F_TEACH_PROCESS;
 		TRACE_STATE("peer elected to teach lesson to local peer", PEERS_EV_SESS_NEW|PEERS_EV_SESS_RESYNC, NULL, peer);
 	}
@@ -3307,6 +3314,12 @@
 				goto switchstate;
 
 send_msgs:
+				if (curpeer->local && appctx_is_back(appctx) &&
+				    curpeer->learnstate == PEER_LR_ST_PROCESSING && msg_done &&
+				    tick_is_expired(curpeer->heartbeat, now_ms)) {
+					curpeer->flags |= PEER_F_HEARTBEAT;
+					curpeer->heartbeat = tick_add(now_ms, MS_TO_TICKS(PEER_HEARTBEAT_TIMEOUT));
+				}
 				if (curpeer->flags & PEER_F_HEARTBEAT) {
 					curpeer->flags &= ~PEER_F_HEARTBEAT;
 					repl = peer_send_heartbeatmsg(appctx, curpeer, curpeer->peers);

With this patch, the 100,000-entry mTLS case completes in 12.55 seconds, where the same build without it stopped at 43,600 entries with 0x10400004. A deliberately slower mTLS handover completed in 76.45 seconds with 25 progress heartbeats, so the result does not depend on the discarded 60-second ceiling. A deliberately stalled relay still made each session abort at five seconds.

An isolated test shaped like the production cluster transferred three mTLS tables of 1.5 million entries each with eight threads. All 4.5 million entries arrived in 28.17 seconds on the first session, the learner sent nine progress heartbeats, and synchronization finished with 0x11000003. Five repeated local reloads, the #3518 remote full-resynchronization reproducer, and all four upstream peer VTests passed.

This is an experimental patch for upstream review. There may be a preferable way to represent the local teaching phase or its progress deadline.

What is your configuration?

The reproducer generates the configuration with temporary paths and free loopback ports. Before the reload it rewrites the file so the new worker's peer listener moves to a fresh port and a TCP listener on the old port forwards into the paced relay, which forwards to the new port. The old worker still connects to the old port, so only its handover is paced. Initial configuration (example ports):

global
  localpeer lab
  nbthread 8
  stats socket /tmp/example/admin.sock level admin
peers synced
  bind 127.0.0.1:19001
  server lab
  table marker type ipv6 size 100100 expire 1h store gpt(1)

Configuration in place when the reload signal is sent (19002 is the new peer port, 19003 the relay):

global
  localpeer lab
  nbthread 8
  stats socket /tmp/example/admin.sock level admin
peers synced
  bind 127.0.0.1:19002
  server lab
  table marker type ipv6 size 100100 expire 1h store gpt(1)
listen handover-transport
  mode tcp
  bind 127.0.0.1:19001
  timeout connect 1s
  timeout client 1m
  timeout server 1m
  server paced 127.0.0.1:19003

The --tls variant adds a temporary self-signed certificate with verify required on both the bind line and the server line.

Output of haproxy -vv

Unmodified 3.4.6 built with make TARGET=linux-glibc USE_OPENSSL= USE_LUA= USE_PCRE2=, used as the negative control:

HAProxy version 3.4.6-56332c5 2026/09/28 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2031.
Known bugs: http://www.haproxy.org/bugs/bugs-3.4.6.html
Running on: Linux 6.12.107+deb13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.12.107-1 (2026-08-29) x86_64
Build options : 
  TARGET  = linux-glibc
  CC      = cc
  CFLAGS  = -O2 -g -fwrapv -fvect-cost-model=very-cheap
  OPTIONS = USE_OPENSSL= USE_LUA= USE_PCRE2=
  DEBUG   = 

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL -ECH -ENGINE +EPOLL -EVPORTS +GETADDRINFO +HAVE_TCP_MD5SIG -KQUEUE +KTLS -LIBATOMIC +LIBCRYPT +LINUX_CAP +LINUX_SPLICE +LINUX_TPROXY -LUA -MATH -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER -OPENSSL -OPENSSL_AWSLC -OPENSSL_WOLFSSL -OT -PCRE -PCRE2 -PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PROCCTL -PROMEX -PTHREAD_EMULATION -QUIC -QUIC_OPENSSL_COMPAT +RT +SHM_OPEN +SLZ -SSL -STATIC_PCRE -STATIC_PCRE2 +TFO +THREAD +THREAD_DUMP +TPROXY +TRACE -WURFL -ZLIB
Detected feature list : +HAVE_WORKING_TCP_MD5SIG

Default settings :
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with multi-threading support (MAX_TGROUPS=32, MAX_THREADS=1024, default=8).
Built with network namespace support.
Built with libslz for stateless compression.
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built without PCRE or PCRE2 support (using libc's regex instead)
Encrypted password support via crypt(3): yes
Built with gcc compiler version 14.2.0

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
         h2 : mode=HTTP  side=FE|BE  mux=H2    flags=HTX|HOL_RISK|NO_UPG
  <default> : mode=HTTP  side=FE|BE  mux=H1    flags=HTX
         h1 : mode=HTTP  side=FE|BE  mux=H1    flags=HTX|NO_UPG
       fcgi : mode=HTTP  side=BE     mux=FCGI  flags=HTX|HOL_RISK|NO_UPG
  <default> : mode=SPOP  side=BE     mux=SPOP  flags=HOL_RISK|NO_UPG
       spop : mode=SPOP  side=BE     mux=SPOP  flags=HOL_RISK|NO_UPG
  <default> : mode=TCP   side=FE|BE  mux=PASS  flags=
       none : mode=TCP   side=FE|BE  mux=PASS  flags=NO_UPG

Available services : none

Available filters :
	[BWLIM] bwlim-in
	[BWLIM] bwlim-out
	[CACHE] cache
	[COMP] comp-req
	[COMP] comp-res
	[COMP] compression
	[FCGI] fcgi-app
	[SPOE] spoe
	[TRACE] trace

The failing run quoted in the description is from this build on 2026-10-02. The same source with only the patch above applied completes all 100,000 entries in 12.35 seconds with 0x11000003. The behaviour also reproduces with a full AWS-LC/QUIC/Lua/PCRE2 build.

Last Outputs and Backtraces

There is no crash or backtrace. The useful trace sequence from the teaching worker is:

peer elected to teach lesson to local peer
full/partial resync finished
[approximately five seconds while the learner is still receiving entries]
peer session stopping
peer session released

Additional Information

This is distinct from #3517 to #3520. It reproduces on stock 3.4.6 without those patches and concerns the local old-worker/new-worker stream timeout rather than shared shutdown state, heartbeat suppression during remote resynchronization, connection replacement, or task deadline selection. #3518 is the closest relative: the same hardcoded five-second timeout and independent-stream behaviour, hit on the remote resync path when a pending local update suppresses the learner's heartbeats. The same five-second timeout and independent-stream setup are present in current master as of 2026-10-02.

Field results: a 3.4.6 build carrying this patch together with the fixes proposed in #3517, #3518, #3519 and #3520 was deployed to a four-node production cluster on 2026-10-02. Each node has two peers sections, the nodes talk over mTLS, and the replicated tables hold 1.3 to 2.4 million entries each. After deployment, reloading the nodes one at a time and then all four at once preserved every checked entry and test marker. The local handovers took 15 to 33 seconds and the new worker sent three to six progress heartbeats during each.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions