Skip to content

Instantly share code, notes, and snippets.

@falsecz
Created July 16, 2026 07:31
Show Gist options
  • Select an option

  • Save falsecz/d606e19acd5878554d3bdccb9089371d to your computer and use it in GitHub Desktop.

Select an option

Save falsecz/d606e19acd5878554d3bdccb9089371d to your computer and use it in GitHub Desktop.
esp-modbus #161 EPROT-55 — reproducer + partial patch for v2.1.3

esp-modbus TCP slave — TID scope patch (issue #161 / EPROT-55, tested against v2.1.3)

TL;DR: on esp-modbus v2.1.3 TCP slave, two concurrent TCP clients whose requests land in the same millisecond window trigger persistent latency degradation on the surviving connection — even after the "attacker" client disconnects. guaranteed_repro.py reproduces it 100 %. The v2.1.3 fixes for #161 (cc8f3f6, c83a7ea) address a related wake-race and event-loop starvation, but by their own commit messages do not cover the state leak we observe. This gist contains:

  • the reproduction script (Python, pymodbus)
  • a patch for one of the two identified root causes (cross-connection TID collision)
  • notes on the second root cause (head-of-queue blocking) which requires a bigger refactor

Reproduction

uv run guaranteed_repro.py <DEVICE_IP> --recovery 60

Three phases:

  1. conn A alone (baseline) — 30 s, single reader, holding[1000..1006] every 1 s at wall-clock tick → median latency ~30-65 ms.
  2. conn A + conn B — B opens, sends 10 wall-clock-synchronized reads of the same registers, then closes.
  3. conn A alone again (recovery) — 60 s observation.

The critical detail is wait_for_next_tick(interval, stop) — every client sends its request at math.ceil(now / interval) * interval, so requests from different sockets land in the same ms window. Without this synchronization the race is much less reproducible.

Typical measured values on FW built against esp-modbus v2.1.3

phase median latency ratio to baseline
conn A alone 30 ms 1.0×
conn A + conn B (during) 1000–3000 ms 30–100×
conn A alone again (60 s after B disconnect) 150–200 ms 3–5×

The third row is the important one — degradation persists after conn B disconnects, and clears only on device reboot.


Root causes identified in v2.1.3 source

(1) Head-of-queue blocking with 120 s expiry — NOT fixed by this patch

modbus/mb_ports/tcp/port_tcp_slave.c, function mbs_on_recv_data, around line 435:

if (transaction_item_get_state(item) == QUEUED) {
    if (mb_port_event_res_take(&port_obj->base, TRANSACTION_TICKS)) {   // 20 ms
        (void)mb_drv_clear_status_flag(drv_obj, MB_FLAG_TRANSACTION_READY);
    } else {
        if (port_get_timestamp() - transaction_item_get_tick(item)
              > MB_DROP_TRANSACTION_TIME_US) {
            ESP_LOGD("Transaction TID:0x%04x is expired.");   // LOG ONLY — no delete

MB_DROP_TRANSACTION_TIME_US = CONFIG_FMB_TCP_KEEP_ALIVE_TOUT_SEC × 2 × 1e6 = 120 s at default keep-alive. When conn B's QUEUED item sits at the head of the shared per-port STAILQ (port_obj->transaction) and the FSM resource semaphore is contended, conn A's later items sit behind it until the 120 s expiry runs — even if conn B already disconnected.

Real fix is per-node transaction lists: split port_obj->transaction into pnode->transaction. That's a 200–500 line refactor with corresponding changes in the event dispatcher (mb_drv_tcp_task). Out of scope for this gist.

Quick mitigation without code changes:

CONFIG_FMB_TCP_KEEP_ALIVE_TOUT_SEC=5    # cuts persistence from 120 s to 10 s

(2) Cross-connection TID collision — FIXED by this patch

modbus/mb_ports/common/mb_transaction.c, transaction_get(msg_id) and transaction_delete(msg_id), around line 75 / 163:

Both look up transactions by TID only, no fd filter. Two fresh connections both start counting TIDs from 1. A transaction_delete(tid) triggered by conn B's response processing can therefore remove conn A's in-flight transaction, causing conn A's next response to hit the "transaction not found for TID" ESP_LOGE path in mbs_on_send_data (port_tcp_slave.c ~line 574).

The transaction_item_t struct already carries node_id (used by transaction_delete_by_node_id in the error handler). We just need to use it during lookup.


The patch

See esp-modbus-2.1.3-tid-scope.patch. Apply with:

cd path/to/esp-modbus  # v2.1.3 checkout
git apply --check esp-modbus-2.1.3-tid-scope.patch
git apply esp-modbus-2.1.3-tid-scope.patch

Scope: 3 files, ~10 lines. Adds an int node_id argument to transaction_get() and transaction_delete(); callers that know the originating socket pass event_info->opt_fd. node_id < 0 means "match any" for backward-compatibility with callers that don't have that context.

Expected effect after applying:

  • Cross-connection deletes and lookups should stop. The Transaction TID:0x%04x not found for send. ESP_LOGE lines should disappear from the log under concurrent load.
  • The persistence part of the bug will shrink but not disappear — head-of-queue blocking (root cause 1) is still in play. Expected post-disconnect ratio: from 3–5× down to 1.5–2× baseline within MB_DROP_TRANSACTION_TIME_US.
  • No behavior change under single-client load.

Please test and file results on issue #161. If Espressif merges (or provides a better fix), even better.


References

From: guaranteed_repro <noreply@example.invalid>
Date: 2026-07-16
Subject: [PATCH] esp-modbus TCP slave: scope transaction lookup by node_id
The shared per-port transaction STAILQ (port_obj->transaction) is looked up
by TID alone in transaction_get() and transaction_delete(). Two fresh TCP
client connections both start their TID counter at 1, so a delete triggered
by one connection's response processing can remove the other connection's
in-flight transaction.
This patch scopes transaction_get() / transaction_delete() to a specific
node_id (== fd == pnode->index) when the caller has that context.
node_id < 0 means "match any", preserving existing behavior for callers
that legitimately look up across connections (e.g. transaction_delete_expired).
Only the TID-collision root cause is addressed here; head-of-queue blocking
via the shared STAILQ + MB_DROP_TRANSACTION_TIME_US remains and requires a
per-node transaction list refactor.
---
modbus/mb_ports/common/mb_transaction.c | 10 ++++++----
modbus/mb_ports/common/mb_transaction.h | 4 ++--
modbus/mb_ports/tcp/port_tcp_slave.c | 6 +++---
3 files changed, 11 insertions(+), 9 deletions(-)
diff --git a/modbus/mb_ports/common/mb_transaction.h b/modbus/mb_ports/common/mb_transaction.h
--- a/modbus/mb_ports/common/mb_transaction.h
+++ b/modbus/mb_ports/common/mb_transaction.h
@@ -XX,XX +XX,XX @@
esp_err_t transaction_init(transaction_t **transaction);
esp_err_t transaction_destroy(transaction_t *transaction);
esp_err_t transaction_insert(transaction_t *transaction, int node_id,
uint16_t msg_id, uint8_t *pbuf, size_t length);
-transaction_item_t *transaction_get(transaction_t *transaction, uint16_t msg_id);
-esp_err_t transaction_delete(transaction_t *transaction, uint16_t msg_id);
+transaction_item_t *transaction_get(transaction_t *transaction, uint16_t msg_id, int node_id);
+esp_err_t transaction_delete(transaction_t *transaction, uint16_t msg_id, int node_id);
esp_err_t transaction_delete_by_node_id(transaction_t *transaction, int node_id);
esp_err_t transaction_delete_expired(transaction_t *transaction, uint64_t threshold_us);
transaction_item_t *transaction_get_first(transaction_t *transaction);
diff --git a/modbus/mb_ports/common/mb_transaction.c b/modbus/mb_ports/common/mb_transaction.c
--- a/modbus/mb_ports/common/mb_transaction.c
+++ b/modbus/mb_ports/common/mb_transaction.c
@@ -70,12 +70,14 @@
-transaction_item_t *transaction_get(transaction_t *transaction, uint16_t msg_id)
+transaction_item_t *transaction_get(transaction_t *transaction, uint16_t msg_id, int node_id)
{
transaction_item_t *item;
CRITICAL_SECTION_LOCK(transaction->lock);
STAILQ_FOREACH(item, &transaction->head, entries) {
- if (item->msg_id == msg_id) {
+ // node_id < 0 → match any (backward-compat for existing callers
+ // that legitimately search across all connections).
+ if (item->msg_id == msg_id &&
+ (node_id < 0 || item->node_id == node_id)) {
CRITICAL_SECTION_UNLOCK(transaction->lock);
return item;
}
}
CRITICAL_SECTION_UNLOCK(transaction->lock);
return NULL;
}
@@ -160,10 +162,10 @@
-esp_err_t transaction_delete(transaction_t *transaction, uint16_t msg_id)
+esp_err_t transaction_delete(transaction_t *transaction, uint16_t msg_id, int node_id)
{
- transaction_item_t *item = transaction_get(transaction, msg_id);
+ transaction_item_t *item = transaction_get(transaction, msg_id, node_id);
if (!item) {
return ESP_ERR_NOT_FOUND;
}
CRITICAL_SECTION_LOCK(transaction->lock);
STAILQ_REMOVE(&transaction->head, item, transaction_item, entries);
CRITICAL_SECTION_UNLOCK(transaction->lock);
free(item->pbuf);
free(item);
return ESP_OK;
}
diff --git a/modbus/mb_ports/tcp/port_tcp_slave.c b/modbus/mb_ports/tcp/port_tcp_slave.c
--- a/modbus/mb_ports/tcp/port_tcp_slave.c
+++ b/modbus/mb_ports/tcp/port_tcp_slave.c
@@ -498,7 +498,8 @@ static esp_err_t mbs_on_send_data(...)
uint16_t tid = MB_TCP_MBAP_GET_TID(sbuf);
- transaction_item_t *item = transaction_get(port_obj->transaction, tid);
+ transaction_item_t *item = transaction_get(port_obj->transaction, tid,
+ event_info->opt_fd);
if (!item) {
ESP_LOGE(TAG, "Transaction TID:0x%04x not found for send.", tid);
return ESP_FAIL;
}
@@ -519,7 +520,7 @@ static esp_err_t mbs_on_send_data(...)
// busy exception branch — remove the transaction so the client can retry
- (void)transaction_delete(port_obj->transaction, tid);
+ (void)transaction_delete(port_obj->transaction, tid, event_info->opt_fd);
# /// script
# requires-python = ">=3.10"
# dependencies = ["pymodbus>=3.0"]
# ///
"""Guaranteed reproducer for esp-modbus TCP slave concurrency bug — one script,
one terminal window. Related to issue espressif/esp-modbus#161 (EPROT-55).
Flow (about 2-3 minutes):
1. (optional) restart the device — pass --restart if you have restart_device.py
2. BASELINE: 30 s single reader (conn A). Expect ~30-150 ms latency.
3. ATTACK: open N=1 extra connection (conn B), send 10 wall-clock synced
reads of the same holding registers, then close.
4. RECOVERY (optional): keep conn A alive for --recovery seconds after
conn B closes, to measure how long the degradation persists.
5. VERDICT: median latency baseline vs. under-attack, ratio.
Key trick: all clients wait for `math.ceil(now / interval) * interval`, so
their requests hit the device in the same millisecond window — this is what
triggers the race deterministically. Independently started clients tend to
end up in opposite phase and miss the race.
Usage:
uv run guaranteed_repro.py <DEVICE_IP> --recovery 60
"""
import argparse
import contextlib
import math
import statistics
import sys
import threading
import time
from dataclasses import dataclass, field
from pymodbus.client import ModbusTcpClient
PORT = 502
UNIT_ID = 1
READ_REG = 1000
READ_COUNT = 7
INTERVAL_S = 1.0
BASELINE_S = 30.0
ATTACK_S = 90.0
N_EXTRA_CONNS = 1
N_REQS = 10
def wait_for_next_tick(interval: float, stop: threading.Event) -> None:
"""Čeká do dalšího wall-clock tiku (celé sekundy).
Všichni klienti, kteří tohle používají, pošlou svůj request ve stejný okamžik
→ maximalizace race condition mezi spojeními, což je to, co bug spouští."""
now = time.time()
next_tick = math.ceil((now + 1e-3) / interval) * interval
delay = next_tick - now
if delay > 0:
stop.wait(delay)
# ANSI barvy
class C:
RESET = "\033[0m"
DIM = "\033[2m"
RED = "\033[31m"
GREEN = "\033[32m"
YELLOW = "\033[33m"
BLUE = "\033[34m"
MAGENTA = "\033[35m"
CYAN = "\033[36m"
BOLD = "\033[1m"
def color(text: str, code: str) -> str:
return f"{code}{text}{C.RESET}"
# Barevná paleta per spojení (A = magenta, B = cyan, C = yellow, D = green, E = blue)
CONN_COLORS = [C.MAGENTA, C.CYAN, C.YELLOW, C.GREEN, C.BLUE]
def conn_color(label: str) -> str:
idx = ord(label) - ord("A")
return CONN_COLORS[idx % len(CONN_COLORS)]
def color_for_lat(lat_ms: float) -> str:
if lat_ms >= 2000:
return C.RED + C.BOLD
if lat_ms >= 1000:
return C.RED
if lat_ms >= 500:
return C.YELLOW
if lat_ms >= 200:
return C.CYAN
return C.GREEN
@dataclass
class RunState:
primary_lats: list[float] = field(default_factory=list)
primary_phase: list[str] = field(default_factory=list) # "baseline" / "attack" / "recovery"
phase: str = "baseline"
lock: threading.Lock = field(default_factory=threading.Lock)
def make_client(host: str) -> ModbusTcpClient:
c = ModbusTcpClient(host, port=PORT, timeout=5.0, retries=0)
if not c.connect():
raise RuntimeError(f"connect failed to {host}:{PORT}")
if hasattr(c, "set_max_no_responses"):
c.set_max_no_responses(10**9)
return c
def _log_event(conn_label: str, event: str, detail: str, style: str = "") -> None:
ts = time.strftime("%H:%M:%S")
tag = color(f"conn {conn_label}", C.BOLD + conn_color(conn_label))
ev = color(f"{event:<5}", style or C.DIM)
print(f"[{ts}] {tag} {ev} {detail}", flush=True)
def client_loop(
host: str,
conn_label: str, # "A", "B", "C", ...
state: RunState,
stop: threading.Event,
is_primary: bool,
max_reqs: int = 0,
) -> None:
reg_range = f"holding[{READ_REG}..{READ_REG + READ_COUNT - 1}]"
try:
c = make_client(host)
except Exception as e:
_log_event(conn_label, "OPEN", color(f"FAILED {e}", C.RED), C.RED)
return
_log_event(
conn_label,
"OPEN",
f"tcp://{host}:{PORT} will read {reg_range} every {INTERVAL_S:.0f} s (wall-clock synced)",
C.GREEN,
)
sent = 0
try:
while not stop.is_set():
if max_reqs and sent >= max_reqs:
break
t0 = time.perf_counter()
ok = True
try:
r = c.read_holding_registers(READ_REG, count=READ_COUNT, device_id=UNIT_ID)
if r.isError():
ok = False
except Exception:
ok = False
lat = (time.perf_counter() - t0) * 1000
sent += 1
if is_primary:
with state.lock:
state.primary_lats.append(lat if ok else -1)
phase = state.phase
state.primary_phase.append(phase)
phase_lats = [l for l, p in zip(state.primary_lats, state.primary_phase)
if p == phase and l > 0]
run_avg = statistics.mean(phase_lats) if phase_lats else 0.0
extra = color(f" phase={phase:<8} run-avg={run_avg:6.0f} ms", C.DIM)
else:
extra = color(f" ({sent}/{max_reqs} reqs)", C.DIM) if max_reqs else ""
if not ok:
detail = color(f"{reg_range} ERROR {lat:6.0f} ms", C.RED) + extra
_log_event(conn_label, "READ", detail, C.RED)
else:
lat_style = color_for_lat(lat)
detail = f"{reg_range} " + color(f"lat={lat:6.0f} ms", lat_style) + extra
_log_event(conn_label, "READ", detail, lat_style)
if max_reqs and sent >= max_reqs:
break
wait_for_next_tick(INTERVAL_S, stop)
finally:
with contextlib.suppress(Exception):
c.close()
close_detail = f"sent {sent} req(s)" + (f" of {max_reqs}" if max_reqs else "")
_log_event(conn_label, "CLOSE", close_detail, C.YELLOW)
def banner(text: str, style: str) -> None:
line = "═" * 68
print()
print(color(line, style))
print(color(f" {text}", style + C.BOLD))
print(color(line, style))
print()
def main() -> int:
ap = argparse.ArgumentParser(description=__doc__.splitlines()[0])
ap.add_argument("host", help="Modbus TCP slave host (device IP)")
ap.add_argument("--restart", action="store_true",
help="call restart_device.restart_device(host) before the test "
"(you must provide restart_device.py yourself — the mechanism "
"is device-specific: HTTP call, GPIO reset, esp_restart via "
"OTA channel, etc.). If not set, reboot the device manually "
"between runs for clean baseline.")
ap.add_argument("--baseline", type=float, default=BASELINE_S,
help=f"baseline seconds — conn A alone (default {BASELINE_S:.0f})")
ap.add_argument("--attack", type=float, default=ATTACK_S,
help=f"safety cap on attack window in seconds (default {ATTACK_S:.0f})")
ap.add_argument("--extra-conns", type=int, default=N_EXTRA_CONNS,
help=f"number of additional concurrent connections B, C, ... "
f"(default {N_EXTRA_CONNS})")
ap.add_argument("--reqs", type=int, default=N_REQS,
help=f"requests per extra connection (0 = unlimited, runs for full "
f"--attack window; default {N_REQS})")
ap.add_argument("--recovery", type=float, default=0.0,
help="seconds to observe conn A AFTER the extra connections close "
"(measures persistence of degradation)")
args = ap.parse_args()
if args.restart:
try:
from restart_device import restart_device # user-provided
except ImportError:
print("ERROR: --restart was requested but restart_device.py is not "
"importable. Provide your own restart_device.py with a function "
"restart_device(host) — or omit --restart and reboot manually.",
file=sys.stderr)
return 2
banner(f"STEP 1/3 restart {args.host}", C.YELLOW)
restart_device(args.host)
state = RunState()
primary_stop = threading.Event()
attacker_stop = threading.Event()
primary_thread = threading.Thread(
target=client_loop,
args=(args.host, "A", state, primary_stop, True, 0),
daemon=True,
)
primary_thread.start()
banner(f"STEP 2/3 BASELINE — conn A alone, {args.baseline:.0f} s", C.CYAN)
print(color(f"(expected latency: ~30-150 ms, healthy)", C.DIM))
print()
time.sleep(args.baseline)
with state.lock:
baseline_lats = [l for l, p in zip(state.primary_lats, state.primary_phase)
if p == "baseline" and l > 0]
baseline_avg = statistics.mean(baseline_lats) if baseline_lats else 0.0
extras_desc = ", ".join(chr(ord("B") + i) for i in range(args.extra_conns))
banner(
f"STEP 3/3 open conn {extras_desc}{args.reqs or 'unlimited'} req(s) each",
C.RED,
)
print(color(
f"(conn A keeps running — watch its latency jump. Baseline avg = {baseline_avg:.0f} ms)",
C.DIM,
))
print()
with state.lock:
state.phase = "attack"
# Další spojení = conn B, C, D, ...
extra_threads = []
for i in range(args.extra_conns):
conn_label = chr(ord("B") + i) # B, C, D, ...
t = threading.Thread(
target=client_loop,
args=(args.host, conn_label, state, attacker_stop, False, args.reqs),
daemon=True,
)
extra_threads.append(t)
t.start()
try:
if args.reqs:
# wait for all extra connections to finish, with a safety cap
deadline = time.monotonic() + args.attack
while any(t.is_alive() for t in extra_threads) and time.monotonic() < deadline:
time.sleep(0.2)
else:
time.sleep(args.attack)
except KeyboardInterrupt:
print(color("\n# interrupted", C.DIM))
attacker_stop.set()
for t in extra_threads:
t.join(timeout=2)
# RECOVERY phase — conn A alone again, watch whether latency recovers
if args.recovery > 0:
banner(
f"RECOVERY conn {extras_desc} gone, conn A alone for {args.recovery:.0f} s — will it recover?",
C.YELLOW,
)
with state.lock:
state.phase = "recovery"
try:
time.sleep(args.recovery)
except KeyboardInterrupt:
print(color("\n# interrupted", C.DIM))
primary_stop.set()
primary_thread.join(timeout=2)
# verdict
with state.lock:
base_lats = [l for l, p in zip(state.primary_lats, state.primary_phase)
if p == "baseline" and l > 0]
atk_lats = [l for l, p in zip(state.primary_lats, state.primary_phase)
if p == "attack" and l > 0]
rec_lats = [l for l, p in zip(state.primary_lats, state.primary_phase)
if p == "recovery" and l > 0]
banner("VERDICT", C.YELLOW)
if base_lats and atk_lats:
# Median (p50) místo avg — jeden 1500 ms spike v baseline by jinak
# strhl avg z 65 na 200+ ms a ratio by kleslo pod detekční hranici.
b_med = statistics.median(base_lats)
b_avg = statistics.mean(base_lats)
b_max = max(base_lats)
# Skip prvních 5 s attack okna — startup transient
plateau = atk_lats[5:] if len(atk_lats) > 5 else atk_lats
p_med = statistics.median(plateau) if plateau else 0.0
p_avg = statistics.mean(plateau) if plateau else 0.0
p_max = max(plateau) if plateau else 0.0
ratio = p_med / b_med if b_med > 0 else float("inf")
print(color(f" conn A alone ", C.CYAN) +
f"n={len(base_lats):3d} median = {color(f'{b_med:6.0f}', C.GREEN)} ms "
f"avg = {b_avg:6.0f} ms max = {b_max:6.0f} ms")
print(color(f" conn A + others ", C.RED) +
f"n={len(plateau):3d} median = {color(f'{p_med:6.0f}', color_for_lat(p_med))} ms "
f"avg = {color(f'{p_avg:6.0f}', color_for_lat(p_avg))} ms max = {p_max:6.0f} ms")
print(color(f" (plateau — skipping first 5 s of concurrent activity)", C.DIM))
if rec_lats:
r_med = statistics.median(rec_lats)
r_avg = statistics.mean(rec_lats)
r_max = max(rec_lats)
r_ratio = r_med / b_med if b_med > 0 else float("inf")
print(color(f" conn A alone again ", C.YELLOW) +
f"n={len(rec_lats):3d} median = {color(f'{r_med:6.0f}', color_for_lat(r_med))} ms "
f"avg = {color(f'{r_avg:6.0f}', color_for_lat(r_avg))} ms max = {r_max:6.0f} ms")
print(color(f" (others disconnected — {r_ratio:.1f}× baseline)", C.DIM))
print()
style = C.RED + C.BOLD if ratio >= 3.0 else C.YELLOW if ratio >= 1.5 else C.GREEN
print(color(f" during ratio {ratio:.1f}× baseline (median vs median)", style))
if rec_lats:
r_style = C.RED + C.BOLD if r_ratio >= 3.0 else C.YELLOW if r_ratio >= 1.5 else C.GREEN
r_verdict = "persistent damage" if r_ratio >= 3.0 else "partial recovery" if r_ratio >= 1.5 else "fully recovered"
print(color(f" after ratio {r_ratio:.1f}× baseline → {r_verdict}", r_style))
print()
if ratio >= 3.0:
print(color(" ✅ BUG REPRODUCED — primary reader latency degraded significantly", C.RED + C.BOLD))
print(color(" under load from other TCP clients on port 502.", C.RED))
return 0
elif ratio >= 1.5:
print(color(" ⚠️ mild degradation only — retry or increase --extra-conns / --reqs", C.YELLOW))
return 1
else:
print(color(" ✅ no degradation observed — bug may be fixed on this firmware", C.GREEN))
return 1
else:
print(color(" no samples — connection error?", C.RED))
return 2
if __name__ == "__main__":
sys.exit(main())
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment