From patchwork Wed Sep 2 22:07:42 2026 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Aeliton Silva (ESP - MGC NETP.SDN)" X-Patchwork-Id: 2297061 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@legolas.ozlabs.org Authentication-Results: legolas.ozlabs.org; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=wK5nMkKy; dkim-atps=neutral Authentication-Results: legolas.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org (client-ip=2605:bc80:3010::138; helo=smtp1.osuosl.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=patchwork.ozlabs.org) Received: from smtp1.osuosl.org (smtp1.osuosl.org [IPv6:2605:bc80:3010::138]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange x25519 server-signature ECDSA (secp384r1) server-digest SHA384) (No client certificate requested) by legolas.ozlabs.org (Postfix) with ESMTPS id 4hZxgS5zzHz1xvf for ; Thu, 03 Sep 2026 08:08:04 +1000 (AEST) Received: from localhost (localhost [127.0.0.1]) by smtp1.osuosl.org (Postfix) with ESMTP id 1667080E9D; Wed, 2 Sep 2026 22:08:03 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp1.osuosl.org ([127.0.0.1]) by localhost (smtp1.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id Wx3nTjS5axuB; Wed, 2 Sep 2026 22:08:00 +0000 (UTC) ARC-Filter: OpenARC Filter v1.3.0 smtp1.osuosl.org 9D01980E52 Authentication-Results: smtp1.osuosl.org; arc=fail smtp.remote-ip="2605:bc80:3010:104::8cd3:938" ARC-Seal: i=2; d=osuosl.org; s=arc; a=rsa-sha256; cv=fail; t=1788386880; b=dFhb3VH6b9YSuJyjT7fSbbJvAsqZcfaAC+nRQlcNQcYyPJ7J9XsEgkJHoOyOjDAZ50zc zkS5HgiPt/LDE6cOXdx+lXSw7P557oSDhjoYQNA4mzimUI2LPl07LrbjmL573phcpmcs3 Z0BXUQQYVlUC8NgRpNi0C0xIR8ytRQEOyauwPDASaV8PKDz++y+2FZWSt3eeX1LNl0JEe ky6mb08kxC+z9X5KHMrAWMlyk0zyVV+RsenMlMRvf5VVi0uTnMyyU6DNnEa+/4iGCp1ay S1qz526HM0GABX+KAhB/9vK1I1MGr+EbCGS6fK/6er6pHoX6XxshuNRieFFgn+sS5fw== ARC-Message-Signature: i=2; d=osuosl.org; s=arc; a=rsa-sha256; c=relaxed/relaxed; t=1788386880; h=X-Comment:Received:X-Original-To:Delivered-To:Received:Received: X-Virus-Scanned:X-Spam-Flag:X-Spam-Score:X-Spam-Level:X-Spam-Status: Received:ARC-Filter:Received-SPF:Received:Received:DKIM-Signature: X-Google-DKIM-Signature:X-Gm-Message-State:X-Gm-Gg:X-Received: Received:From:To:Date:Message-ID:X-Mailer:MIME-Version:Subject: X-BeenThere:X-Mailman-Version:Precedence:List-Id:List-Unsubscribe: List-Archive:List-Post:List-Help:List-Subscribe:Content-Type: Content-Transfer-Encoding:Errors-To:Sender; bh=S2iEMp5bQy6RnHinzv8AlHHP/qC2KBnj0I/xUEMU4yA=; b=lkOAfiNmiH9Ki9FahqIgFvOi1dYfSt8gF2aIfB+LqRvrElsGrSdkt+Dq9lMUfuxO5Iu2 HZ57onWvjCxaRVr+XZdIBdGUWsAczsn505oC9aM51VZssYGDu0OMzibuKvNy5wecXFShW CjQP8sAiFRCq/CdZfEtftKKSA3MC6WiwZb4VSgfRmVh3RiLm38iLqUyXf3qdz73GcdSB7 ZyUERGximkTn13DKXbIhvlfV5ta1PmetadKGd0vL4h+LpwA7s1q/1Ujlmgz/ImrlI7gMv UK+6/w8LpkT3vrXJhDr2G8V+iqvShO6sq8JG0voWWbuCkqgOVF+tAaJyt1HKiCJSg6Q== ARC-Authentication-Results: i=2; smtp1.osuosl.org; dkim=fail reason="signature verification failed" header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=wK5nMkKy; arc=fail smtp.remote-ip="2605:bc80:3010:104::8cd3:938" X-Comment: SPF check N/A for local connections - client-ip=2605:bc80:3010:104::8cd3:938; helo=lists.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver= Authentication-Results: smtp1.osuosl.org; dkim=fail reason="signature verification failed" (2048-bit key) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=wK5nMkKy Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [IPv6:2605:bc80:3010:104::8cd3:938]) by smtp1.osuosl.org (Postfix) with ESMTPS id 9D01980E52; Wed, 2 Sep 2026 22:08:00 +0000 (UTC) Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 84AB7C0418; Wed, 2 Sep 2026 22:08:00 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp3.osuosl.org (smtp3.osuosl.org [IPv6:2605:bc80:3010::136]) by lists.linuxfoundation.org (Postfix) with ESMTP id A35D2C0417 for ; Wed, 2 Sep 2026 22:07:59 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp3.osuosl.org (Postfix) with ESMTP id 7F13A606B6 for ; Wed, 2 Sep 2026 22:07:59 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp3.osuosl.org ([127.0.0.1]) by localhost (smtp3.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id piwneelcbop7 for ; Wed, 2 Sep 2026 22:07:57 +0000 (UTC) ARC-Filter: OpenARC Filter v1.3.0 smtp3.osuosl.org D64616067E Authentication-Results: smtp3.osuosl.org; arc=none smtp.remote-ip="2607:f8b0:4864:20::112f" ARC-Seal: i=1; d=osuosl.org; s=arc; a=rsa-sha256; cv=none; t=1788386877; b=cUALfwcpBL6H9D7lmKRvkfP9Z6ihrXV3tW19jfa4DQBOwwn9Wk8O4FGwSjxFevCuOXVq I7qjU4oqA2boO+k/e4F3PxISohCqMcngf6Ukava/X+GV6oZ5Lk0HmzLHSIULKHsBbQHwl 6gMWVAGV6yzA5TcDbRdzVzyer2QNUdi7YilkVxUFKuc8CNTrdTrzZtkUdkcxDVrB12IAm 8xMrI6eQ7gnvsVno5tUm70M3Dy5c5KJ2l+qiTNjiihSGvOuNR3czWrJbJXdsst82UZ9Mf 4bltQhe86O4FjSAl3fwljJZ0i7fsjj7xyA1oY66RTvOZpTXXOUHUDCh+WEOOudqAtMQ== ARC-Message-Signature: i=1; d=osuosl.org; s=arc; a=rsa-sha256; c=relaxed/relaxed; t=1788386877; h=Received-SPF:Received:DKIM-Signature:X-Google-DKIM-Signature: X-Gm-Message-State:X-Gm-Gg:X-Received:Received:From:To:Cc:Subject: Date:Message-ID:X-Mailer:MIME-Version:Content-Transfer-Encoding: Content-Type; bh=HdJgwqmbZBU34fQDsfYIM/EdC405Hc40525LRUU7AsY=; b=qCgtcea4bJ4jc/UkHNamO4MGqz9ptDh3hZK+7HCTh3/leB/0O3W9BqNBNkTWkGMpjSfi 88FB1/wm3I1QL0Pr0zn0evVFy1dDX4bHnuM3RYUGMAWMtY2bbd1vBxGuLlJ2GTM6SImIC JXyH4H88adTMNzElEd61oAndfA3M2r9kxIIQWLWmMvsAWoi3mfrm9eeTcsjtWf9zPuMQ0 ZfdB/fam80mSB03hiegC9a8TR2uYIjr+nKwm/EifEhHpTHHbNO823akKm3nA6jH3ncuCH 7l7nBSHbt7ryvQVbPjAKj67f0lXFZ0AzctiPCJz9x5fWuaoZOLJ5jP/B7tSApPvqWJw== ARC-Authentication-Results: i=1; smtp3.osuosl.org; dmarc=pass header.from=magalu.cloud; dkim=pass header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=wK5nMkKy; arc=none smtp.remote-ip="2607:f8b0:4864:20::112f" Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=2607:f8b0:4864:20::112f; helo=mail-yw1-x112f.google.com; envelope-from=aeliton.silva@magalu.cloud; receiver= Authentication-Results: smtp3.osuosl.org; dmarc=pass (p=none dis=none) header.from=magalu.cloud Authentication-Results: smtp3.osuosl.org; dkim=pass (2048-bit key) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=wK5nMkKy Received: from mail-yw1-x112f.google.com (mail-yw1-x112f.google.com [IPv6:2607:f8b0:4864:20::112f]) by smtp3.osuosl.org (Postfix) with ESMTPS id D64616067E for ; Wed, 2 Sep 2026 22:07:56 +0000 (UTC) Received: by mail-yw1-x112f.google.com with SMTP id 00721157ae682-86cba60d4f2so11021787b3.1 for ; Wed, 02 Sep 2026 15:07:56 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=magalu-cloud.20251104.gappssmtp.com; s=20251104; t=1788386875; x=1788991675; darn=openvswitch.org; h=content-type:content-transfer-encoding:mime-version:message-id:date :subject:cc:to:from:from:to:cc:subject:date:message-id:reply-to :content-type; bh=HdJgwqmbZBU34fQDsfYIM/EdC405Hc40525LRUU7AsY=; b=wK5nMkKyc5yHHmYVP2F+dgXyh03O/T/mz1L7gu4nt0tG+pM6A89R+wNLzWzpBbwBxE eruVrYW9+KB/77xQtzArgzdvMppHCYYKxI4N1Fl19pviiUPzPXAzkJXiR9pxsYghlaBu 0CCsnpiSE5+rIhoWea/htVutSK8vCfP170biTIWOYPL01wScQxKuVKWroYtlF4fSywRH 4pKsfvz/hw05qSbU1CawoINlPvWynsvishrwD9K+Wu5ynL5yeOUArfagjNJMxn90SZgP 6ujMb6zGgbfNbiDlRv5EBTC7ZKwvoh1vhrKIk/wIWzjLp1Q6mn6NpSvfstrdMSfGyPIx w5zw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20251104; t=1788386875; x=1788991675; h=content-type:content-transfer-encoding:mime-version:message-id:date :subject:cc:to:from:x-gm-gg:x-gm-message-state:from:to:cc:subject :date:message-id:reply-to:content-type; bh=HdJgwqmbZBU34fQDsfYIM/EdC405Hc40525LRUU7AsY=; b=mytNCHKJfcDqkDTpUiDyMSvMe0nMH19/v/SHtr+IsN0pBExOfgkH3jucbm5LvEsAch /9YlUiLQW/YEdIdKScyXtpFH9eAsOE7JW49QZR83XW+/0qBYsw1++xa4dYPxk7z0FAaU LGiNR3hvJFnLM8caaKRj2yqGxDZOT5WPedz5oCyUX2jYBW2QIGVhvb9Z7ZrgZ0wlZGnZ k9UBdo3/qZLhdg7OWXaqA1pyfFa4ORrqCPS8rW91YXfu1yKB3i63NpjyJe2AOmlTdwmu yqc8apQsdtqR3BLlhoZvAFJGuDHIbyAbNP2Q6qMv5GUjJzaMTb354mDM8AnXDAyeezij FLzg== X-Gm-Message-State: AFuF++kXxdHlzYmyOQrMD1GLtYYjXhMTX/lwMfprOMM3/kwN2KLpDBkD pdWCOoI0xr7IcFYMBST+T9bZ6zlvYy/ivbw5aPwu+bWEz/R4Xpt2M9z6AOwoNaep1SgLE2om5zV G93V9Td3r5A4vfQZfW6SfujRxHuz7TxFOyxxSHZGldlYBAbk7LavkWTj02M/ieBw= X-Gm-Gg: AYBFou0Z64/2NDKQGaBQcD4/CT8LNonyNHK6fA4KvMQr9dsbh+9ga1xAOzb2/sYnitD J1RMuIB84Dog5GCMvLPM86JgFE8RQHwkFUlaRPFAJppdVVQV1UPx27ESHdWQ0/syGuLAXgLWn9x 9OquML9rHtpL6OpbBPeUTiaVH4qg6z50ktdNqUyT2EqGUz1l2yCVF2+XbqK+FeCB9da7+h1eeO4 WDW/ZFe2m3Rby1TtFyKZu+lglU0tNekcDo1NBUXE39HUt9W6gSlXq9OoC1cuPFmx2knvmlb0hVq ARSKUT0xvVoulsj/BVw52bOgy+Wd13J5v3fpyfuXmP6dTbTHabo4DsM22Aw/03b57qbCJeaJSzi amKfJQ9TXjd3uVmv10VJQGjthYtw/KqM41m329EfeUc0M2v4XD7vAILaXNB5LOhvn4DAFZJuAY0 nwo+CeHc8KevS+V7bWstqO0Tc7JLUHf/9d7A664gsZ1Ls/nTp2xebV02ZBFxK5MPrwkLhYYmtXx bE= X-Received: by 2002:a05:690c:698b:b0:856:98e2:6e9b with SMTP id 00721157ae682-86c4d6526b9mr38257407b3.5.1788386873897; Wed, 02 Sep 2026 15:07:53 -0700 (PDT) Received: from WNLEC-7T3RN34.lan ([45.165.21.178]) by smtp.gmail.com with ESMTPSA id 00721157ae682-86c18ac450csm27279497b3.40.2026.09.02.15.07.51 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 02 Sep 2026 15:07:52 -0700 (PDT) From: "Aeliton G. Silva" To: dev@openvswitch.org Date: Wed, 2 Sep 2026 19:07:42 -0300 Message-ID: <20260902220743.4157943-1-aeliton.silva@magalu.cloud> X-Mailer: git-send-email 2.43.0 MIME-Version: 1.0 Subject: [ovs-dev] [PATCH v2 1/2] reconnect: Do not spin on a connection with queued data. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.30 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" Commit 6de8868d (reconnect: Fix broken inactivity probe if there is no other reason to wake up.) enables poll_loop to run immediately on the next millisecond when the probe interval has expired with no receive attempted. Its reasoning notes that "in a correctly written application we should not fall into this case more than once in a row". The problem. An ovsdb-server session whose peer stops reading falls into it forever, causing the ovsdb-server process to burn CPU proportionally to the number of sessions. This behaviour has been observed in production, where a few ovn-octavia-provider clients raised an exception but did not die, keeping their backlog frozen and degrading the ovsdb-server service. The loop spins[1] from the moment the first interval expires -- here t+8 s with the 5 s default, t+201 s with a 180 s probe -- and the cost grows with the session count, because every wake-up walks every connection: 10.5% of a core with the stalled session alone, 21.9% alongside 50 healthy sessions, 42.3% alongside 300. Killing the stalled sessions returns the pass rate and the CPU to baseline at once, which is what separates the pin from load. A merely slow consumer arms the same pin. ovsdb-server sees only its own queue shrinking, and that happens only when the kernel accepts more data -- which depends on the peer acknowledging what it already has, not on the peer reading each byte. The 4 kB/s row below is such a peer. ovsdb-server has no way to know this happened: a session with a standing backlog does not have jsonrpc_session_recv() invoked, which blocks the calls to reconnect_receive_attempted(), so the receive that would move the expiration can never happen unless the peer resumes reading, which a faulty implementation might never do. The fix. The FSM is now aware of how much is queued for the peer, and while anything is queued stops asking for the millisecond retry that would attempt that receive. The queue length is reported where the backlog is updated, so the FSM always has the current value. The probe deadline is still reported, so no session is probed or disconnected at any time it was not before; an ovsdb-server session with a standing backlog reaches neither, as today -- it simply costs nothing to keep. What changes is how often the poll loop wakes. Once the backlog drains the session is read again, so it can reach the probe and answer it, and the ordinary probe interval applies. The 'now + 1' path is where the guard sits, and it remains valid where it is still reached: nothing is queued there, so the receive it exists to permit does happen, and it fires once rather than forever. Testing. A python client reads its backlog at a fixed rate, from not at all to fast enough to keep the queue moving, unpatched against patched on the same tree, against an 8 MB dump at the 5 s inactivity_probe default. It only ever reads, so it never answers a probe: a standing queue blocks the probe, and a reader that drains lets it out unanswered and is dropped. Testing TCP. Unpatched and patched are passes/s, meaned over the seconds of a 72 s run with the session alive, two probe intervals past, and the rig not polling the server -- its replies would otherwise count as the peer's cost. Backlog is the maximum queue ovsdb-server reported via memory/show; dropped runs on to the disconnect, after the whole backlog is consumed. rate backlog dropped unpatched patched 0 kB/s 5.3 MB never 866.5 0.5 4 kB/s 5.2 MB t+1347 s 681.0 0.5 20 kB/s 4.5 MB t+279 s 35.3 0.6 50 kB/s 4.2 MB t+117 s 0.5 0.5 The bottom row does not pin unpatched despite its 4.2 MB, so what arms this is not a backlog but one that stopped moving for a probe interval. The middle rows arm and disarm as the queue stutters, where the patched build holds every row flat rather than merely lower. A row that reads at all drains in the end, and is dropped when it does: t+1347 s, t+279 s and t+117 s as it reads faster. The 0 kB/s peer never moves its queue, so it is the only one never dropped. Testing SSL. ssl_send() clones what it cannot send and reports it sent, so ovsdb's queue holds only the probe queued afterwards, and refuses new data while that clone stands. rate backlog dropped unpatched patched 0 kB/s 41 B never 836.6 0.5 50 kB/s 41 B t+86 s 737.6 0.5 225 kB/s 41 B t+34 s 367.4 0.5 500 kB/s 0 t+19 s 0.7 0.3 50 kB/s pins here and does not over tcp: the same peer, dump and probe interval, with only the queue length differing. Every row that clears the 41 B is dropped once it does, the later the slower it read -- t+86 s, t+34 s, t+19 s -- so a pin and a disconnect are alternatives, decided by whether the queue can move, which is why a wedged peer is never dropped today. Sampled every 0.5 s, the probe appears at t+6 s and the pin arms at t+10 s. 1 - passes/s is voluntary_ctxt_switches in Linux /proc/PID/status, which poll_block() advances once per pass; poll_create_node from "ovs-appctl coverage/show" proxies it where /proc is not available. Fixes: 6de8868d19ea ("reconnect: Fix broken inactivity probe if there is no other reason to wake up.") Signed-off-by: Aeliton G. Silva Assisted-by: Claude Opus 5, Claude Code --- Notes: v2: - Report the queued bytes at the queueing point, not from activity reporting, which left v1 holding a stale zero over TLS. - Guard the 'now + 1' retry alone, not the whole probe deadline, so raft, replication, the IDL and ovsdb-client -- which attempt a receive every pass -- keep the probe and timeout they have today. - Guard the same wake-up in S_IDLE, which the ssl check reaches: its 41 B backlog is the probe queued there and refused. - Add the stall client and two ovsdb-server checks using it, in the shape of "ovsdb-server combines updates on backlogged connections" but over tcp and ssl. lib/jsonrpc.c | 9 +- lib/reconnect.c | 17 +- lib/reconnect.h | 2 + python/ovs/jsonrpc.py | 6 +- python/ovs/reconnect.py | 13 +- tests/automake.mk | 1 + tests/ovsdb-server.at | 141 +++++++++++++++ tests/ovsdb-stall-client.py | 138 +++++++++++++++ tests/reconnect.at | 343 ++++++++++++++++++++++++++++++++++++ tests/test-reconnect.c | 21 ++- tests/test-reconnect.py | 14 +- 11 files changed, 693 insertions(+), 12 deletions(-) create mode 100644 tests/ovsdb-stall-client.py base-commit: b30f621502752463807af7bb8bcf3a0c763544cf diff --git a/lib/jsonrpc.c b/lib/jsonrpc.c index f01a2e56f..844c8110f 100644 --- a/lib/jsonrpc.c +++ b/lib/jsonrpc.c @@ -1048,12 +1048,15 @@ jsonrpc_session_run(struct jsonrpc_session *s) } if (s->rpc) { - size_t backlog; + size_t backlog_before; + size_t backlog_after; int error; - backlog = jsonrpc_get_backlog(s->rpc); + backlog_before = jsonrpc_get_backlog(s->rpc); jsonrpc_run(s->rpc); - if (jsonrpc_get_backlog(s->rpc) < backlog) { + backlog_after = jsonrpc_get_backlog(s->rpc); + reconnect_set_queued_bytes(s->reconnect, backlog_after); + if (backlog_after < backlog_before) { /* Data previously caught in a queue was successfully sent (or * there's an error, which we'll catch below.) * diff --git a/lib/reconnect.c b/lib/reconnect.c index 918ecd203..87dc7715d 100644 --- a/lib/reconnect.c +++ b/lib/reconnect.c @@ -62,6 +62,7 @@ struct reconnect { long long int last_connected; long long int last_disconnected; long long int last_receive_attempt; + size_t queued_bytes; unsigned int max_tries; unsigned int backoff_free_tries; @@ -112,6 +113,7 @@ reconnect_create(long long int now) fsm->last_connected = LLONG_MAX; fsm->last_disconnected = LLONG_MAX; fsm->last_receive_attempt = now; + fsm->queued_bytes = 0; fsm->max_tries = UINT_MAX; fsm->creation_time = now; @@ -340,6 +342,7 @@ reconnect_force_reconnect(struct reconnect *fsm, long long int now) void reconnect_disconnected(struct reconnect *fsm, long long int now, int error) { + fsm->queued_bytes = 0; if (!(fsm->state & (S_BACKOFF | S_VOID))) { /* Report what happened. */ if (fsm->state & (S_ACTIVE | S_IDLE)) { @@ -504,6 +507,16 @@ reconnect_activity(struct reconnect *fsm, long long int now) fsm->last_activity = now; } +/* Tell 'fsm' how much data is currently queued for the peer and has not been + * sent. While it is nonzero the FSM does not ask to be woken up to attempt a + * receive: the caller evidently cannot get data to this peer, so no receive it + * makes can settle anything. */ +void +reconnect_set_queued_bytes(struct reconnect *fsm, size_t queued_bytes) +{ + fsm->queued_bytes = queued_bytes; +} + /* Tell 'fsm' that some attempt to receive data on the connection was made at * 'now'. The FSM only allows probe interval timer to expire when some attempt * to receive data on the connection was received after the time when it should @@ -564,7 +577,7 @@ reconnect_deadline__(const struct reconnect *fsm, long long int now) * we need to wait for the expiration, in the second - we're * already past the deadline. */ return expiration; - } else { + } else if (!fsm->queued_bytes) { /* Time has already passed, but we didn't attempt to receive * anything. We need to wake up and try to receive even if * nothing is pending, so we can update the expiration time or @@ -579,7 +592,7 @@ reconnect_deadline__(const struct reconnect *fsm, long long int now) long long int expiration = fsm->state_entered + fsm->probe_interval; if (now < expiration || fsm->last_receive_attempt >= expiration) { return expiration; - } else { + } else if (!fsm->queued_bytes) { return now + 1; } } diff --git a/lib/reconnect.h b/lib/reconnect.h index 40cc569c4..f3c461d15 100644 --- a/lib/reconnect.h +++ b/lib/reconnect.h @@ -31,6 +31,7 @@ * revisited later.) */ #include +#include struct reconnect *reconnect_create(long long int now); void reconnect_destroy(struct reconnect *); @@ -83,6 +84,7 @@ void reconnect_connected(struct reconnect *, long long int now); void reconnect_connect_failed(struct reconnect *, long long int now, int error); void reconnect_activity(struct reconnect *, long long int now); +void reconnect_set_queued_bytes(struct reconnect *, size_t queued_bytes); void reconnect_receive_attempted(struct reconnect *, long long int now); enum reconnect_action { diff --git a/python/ovs/jsonrpc.py b/python/ovs/jsonrpc.py index 07b454a21..c7ec123e3 100644 --- a/python/ovs/jsonrpc.py +++ b/python/ovs/jsonrpc.py @@ -492,9 +492,11 @@ class Session(object): self.pstream = None if self.rpc: - backlog = self.rpc.get_backlog() + backlog_before = self.rpc.get_backlog() self.rpc.run() - if self.rpc.get_backlog() < backlog: + backlog_after = self.rpc.get_backlog() + self.reconnect.set_queued_bytes(backlog_after) + if backlog_after < backlog_before: # Data previously caught in a queue was successfully sent (or # there's an error, which we'll catch below). # diff --git a/python/ovs/reconnect.py b/python/ovs/reconnect.py index 6b8e49afd..38b2f7e32 100644 --- a/python/ovs/reconnect.py +++ b/python/ovs/reconnect.py @@ -104,7 +104,7 @@ class Reconnect(object): # case we need to wait for the expiration, in the second - # we're already past the deadline. */ return expiration - else: + elif not fsm.queued_bytes: # Time has already passed, but we didn't attempt to receive # anything. We need to wake up and try to receive even if # nothing is pending, so we can update the expiration time @@ -132,7 +132,7 @@ class Reconnect(object): fsm.last_receive_attempt is None or fsm.last_receive_attempt >= expiration): return expiration - else: + elif not fsm.queued_bytes: return now + 1 return None @@ -174,6 +174,7 @@ class Reconnect(object): self.last_connected = None self.last_disconnected = None self.last_receive_attempt = now + self.queued_bytes = 0 self.max_tries = None self.backoff_free_tries = 0 @@ -347,6 +348,7 @@ class Reconnect(object): error. The FSM will back off, then reconnect.""" + self.queued_bytes = 0 if self.state not in (Reconnect.Backoff, Reconnect.Void): # Report what happened if self.state in (Reconnect.Active, Reconnect.Idle): @@ -493,6 +495,13 @@ class Reconnect(object): self._transition(now, Reconnect.Active) self.last_activity = now + def set_queued_bytes(self, queued_bytes): + """Tell this FSM how much data is currently queued for the peer and + has not been sent. While it is nonzero the FSM does not ask to be + woken up to attempt a receive: the caller evidently cannot get data to + this peer, so no receive it makes can settle anything.""" + self.queued_bytes = queued_bytes + def receive_attempted(self, now): """Tell 'fsm' that some attempt to receive data on the connection was made at 'now'. The FSM only allows probe interval timer to expire when diff --git a/tests/automake.mk b/tests/automake.mk index 2f3e4f7ef..fcbb1c439 100644 --- a/tests/automake.mk +++ b/tests/automake.mk @@ -534,6 +534,7 @@ CHECK_PYFILES = \ tests/appctl.py \ tests/flowgen.py \ tests/ovsdb-monitor-sort.py \ + tests/ovsdb-stall-client.py \ tests/system-dpdk-find-device.py \ tests/test-daemon.py \ tests/test-dpparse.py \ diff --git a/tests/ovsdb-server.at b/tests/ovsdb-server.at index 7042b1fd3..c4c99964e 100644 --- a/tests/ovsdb-server.at +++ b/tests/ovsdb-server.at @@ -3161,3 +3161,144 @@ TEST_CONFIG_FILE([complex config], [ } } ], [0]) + +AT_BANNER([OVSDB -- ovsdb-server poll loop]) + +AT_SETUP([ovsdb-server does not spin on a peer that stops reading]) +AT_KEYWORDS([ovsdb server positive tcp poll]) +dnl A session with a standing backlog is never received from, so the probe +dnl expiration never moves and the poll loop can end up waking every +dnl millisecond for as long as the peer stays wedged. poll_create_node counts +dnl one registration per fd per pass, so its rate stands in for the wake-up +dnl rate and is reachable through ovs-appctl. +ordinal_schema > schema +on_exit 'kill `cat *.pid` 2>/dev/null' +AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) +AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile dnl + --remote=ptcp:0:127.0.0.1 db], [0], [ignore], [ignore]) +PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) + +dnl The cumulative poll_create_node counter: one count per fd the poll loop +dnl registers, per pass. It stands in for the pass rate, scaled by however +dnl many fds the server holds, so the check below is a ratio against an idle +dnl baseline sampled in this same run rather than a fixed number. +m4_define([POLL_CREATE_NODE_TOTAL], + [ovs-appctl -t ovsdb-server coverage/show dnl + | awk '/^poll_create_node/ { for (i = 1; i <= NF; i++) dnl + if ($i == "total:") { print $(i + 1); exit } }']) +dnl coverage/show omits a counter it has never hit, so an idle server +dnl that has not folded a poll_create_node total yet prints no line and +dnl the sample comes back empty. Default to 0 rather than letting expr +dnl fail: an empty operand made a malformed comparison here before. +idle_before=`POLL_CREATE_NODE_TOTAL` +sleep 2 +idle_after=`POLL_CREATE_NODE_TOTAL` +: ${idle_before:=0} ${idle_after:=0} +dnl No parentheses: expr takes them as operands and fails with "syntax error: +dnl unexpected ')'". +idle_delta=`expr $idle_after - $idle_before` +idle_rate=`expr $idle_delta / 2` + +dnl Seed the database and then monitor it from a connection that never reads. +dnl The seed is what guarantees a backlog: the reply has to exceed whatever +dnl the socket will buffer, and autotuning does not grow a buffer for a peer +dnl that is not reading. If a host ever buffers all of it, the wait below +dnl times out rather than measuring: raise the row count, do not shrink the +dnl socket, which would stop a reading peer from arming at all. +$PYTHON3 $srcdir/ovsdb-stall-client.py 127.0.0.1:$TCP_PORT 200 60000 dnl + > stall.log 2>&1 & +echo $! > stall.pid +OVS_WAIT_UNTIL([grep -q READY stall.log]) + +dnl The arm is a hard precondition, not an assumption: without a standing +dnl backlog this test would pass on a server that still spins. +OVS_WAIT_UNTIL([test `ovs-appctl -t ovsdb-server memory/show dnl + | tr ' ' '\n' | sed -n 's/^backlog:\(.*\)/\1/p'` -gt 0]) + +dnl Past the 5 s default probe of a command-line remote, which is when the +dnl expiration lapses and the fast wake-up would begin. +sleep 6 + +stalled_before=`POLL_CREATE_NODE_TOTAL` +sleep 2 +stalled_after=`POLL_CREATE_NODE_TOTAL` +: ${stalled_before:=0} ${stalled_after:=0} +stalled_delta=`expr $stalled_after - $stalled_before` +stalled_rate=`expr $stalled_delta / 2` + +dnl Unpatched, this test measured 4266/s (tcp) and 3315/s (ssl) here against +dnl an idle 10/s. A tenfold allowance over the idle baseline leaves the +dnl limit a factor of twenty below the spinning case, with margin both ways. +limit=`expr $idle_rate + 10` +limit=`expr $limit \* 10` +echo "poll_create_node/s: idle $idle_rate stalled $stalled_rate dnl + limit $limit" +AT_CHECK([test -n "$stalled_rate" && test -n "$limit" dnl + && test $stalled_rate -lt $limit], [0], [], []) + +dnl Dropping the wedged peer at the ordinary probe is the CORRECT outcome and +dnl logs an ERR; only the wake-up rate is under test here. +OVSDB_SERVER_SHUTDOWN(["/no response to inactivity probe/d"]) +AT_CLEANUP + +AT_SETUP([ovsdb-server does not spin on an SSL peer that stops reading]) +AT_KEYWORDS([ovsdb server positive ssl tls poll]) +dnl The tcp case above is not enough on its own. Over tcp a stalled +dnl peer leaves megabytes in ovsdb's own queue, so a guard fed a stale +dnl copy of that length still holds a large value and the pin does not +dnl appear. Over ssl the payload is accounted as sent and only the +dnl queued probe stands -- tens of bytes -- which is the shape seen in +dnl production, and the one that catches a guard reading anything but +dnl the live queue length. +AT_SKIP_IF([test "$HAVE_OPENSSL" = no]) +PKIDIR="$abs_top_builddir/tests" +AT_SKIP_IF([expr "$PKIDIR" : ".*[[ '\" +\\]]"]) +ordinal_schema > schema +on_exit 'kill `cat *.pid` 2>/dev/null' +AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) +AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile dnl + --private-key=$PKIDIR/testpki-privkey.pem dnl + --certificate=$PKIDIR/testpki-cert.pem dnl + --ca-cert=$PKIDIR/testpki-cacert.pem dnl + --remote=pssl:0:127.0.0.1 db], [0], [ignore], [ignore]) +PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) + +idle_before=`POLL_CREATE_NODE_TOTAL` +sleep 2 +idle_after=`POLL_CREATE_NODE_TOTAL` +: ${idle_before:=0} ${idle_after:=0} +idle_delta=`expr $idle_after - $idle_before` +idle_rate=`expr $idle_delta / 2` + +$PYTHON3 $srcdir/ovsdb-stall-client.py 127.0.0.1:$SSL_PORT 200 60000 dnl + --tls $PKIDIR/testpki-privkey.pem $PKIDIR/testpki-cert.pem dnl + $PKIDIR/testpki-cacert.pem > stall.log 2>&1 & +echo $! > stall.pid +OVS_WAIT_UNTIL([grep -q READY stall.log]) + +dnl Over ssl the standing queue is small -- the probe alone -- so this +dnl waits for any backlog at all, not for a large one. +OVS_WAIT_UNTIL([test `ovs-appctl -t ovsdb-server memory/show dnl + | tr ' ' '\n' | sed -n 's/^backlog:\(.*\)/\1/p'` -gt 0]) + +sleep 6 + +stalled_before=`POLL_CREATE_NODE_TOTAL` +sleep 2 +stalled_after=`POLL_CREATE_NODE_TOTAL` +: ${stalled_before:=0} ${stalled_after:=0} +stalled_delta=`expr $stalled_after - $stalled_before` +stalled_rate=`expr $stalled_delta / 2` + +limit=`expr $idle_rate + 10` +limit=`expr $limit \* 10` +echo "poll_create_node/s: idle $idle_rate stalled $stalled_rate dnl + limit $limit" +AT_CHECK([test -n "$stalled_rate" && test -n "$limit" dnl + && test $stalled_rate -lt $limit], [0], [], []) + +dnl Dropping the wedged peer at the ordinary probe is the CORRECT outcome and +dnl logs an ERR; only the wake-up rate is under test here. +OVSDB_SERVER_SHUTDOWN(["/no response to inactivity probe/d"]) +AT_CLEANUP diff --git a/tests/ovsdb-stall-client.py b/tests/ovsdb-stall-client.py new file mode 100644 index 000000000..cfa0057f2 --- /dev/null +++ b/tests/ovsdb-stall-client.py @@ -0,0 +1,138 @@ +# Copyright (c) 2026 Open vSwitch project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at: +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Seeds a database, then monitors it from a peer that does not keep up. + +Used by the ovsdb-server checks that a peer which stops taking data does not +drive the poll loop. Two connections are made: the first inserts enough rows +that one monitor reply cannot fit in the socket buffers, the second issues the +monitor and then reads at --throttle bytes a second, so the reply stands in +ovsdb-server's own queue. + +--throttle 0, the default and what those checks use, never reads at all. A +positive rate arms the same case whenever it is slow enough that the queue +does not move within a probe interval, which is a property of the receive +buffer as much as the rate: a receiver defers window updates until a +worthwhile part of its buffer is free, so the queue stalls for roughly +buffer/rate seconds. The socket is left with whatever the kernel gives it, +as a real peer would be. + +Prints READY once the monitor request has been sent. +""" + +import argparse +import json +import socket +import ssl +import sys +import time + +TLS = None # (private key, certificate, CA certificate), or None for plain tcp + + +def connect(target): + host, port = target.rsplit(':', 1) + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + sock.connect((host, int(port))) + if TLS: + key, cert, ca = TLS + ctx = ssl.SSLContext(ssl.PROTOCOL_TLS_CLIENT) + ctx.load_cert_chain(cert, key) + ctx.load_verify_locations(ca) + # No cert for "127.0.0.1"; ovsdb authenticates by CA, not name. + ctx.check_hostname = False + sock = ctx.wrap_socket(sock) + return sock + + +def transact(sock, ops): + sock.sendall(json.dumps({"method": "transact", + "params": ops, "id": 0}).encode()) + buf = b"" + while True: + chunk = sock.recv(65536) + if not chunk: + sys.exit("ovsdb-stall-client: server closed while seeding") + buf += chunk + try: + return json.loads(buf.decode()) + except ValueError: + continue + + +def drain(sock, rate): + """Reads 'rate' bytes a second from 'sock', forever.""" + slice_ = max(1, rate // 10) + while True: + deadline = time.time() + 0.1 + got = 0 + # recv() returns what is buffered, which is less than asked for + # whenever the receive buffer is small. Keep going until the slice + # is filled, or the window is up, so the rate is the one requested. + while got < slice_: + try: + data = sock.recv(slice_ - got) + except OSError: + return + if not data: + return + got += len(data) + if time.time() >= deadline: + break + delay = deadline - time.time() + if delay > 0: + time.sleep(delay) + + +def main(argv): + global TLS + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0]) + parser.add_argument("target", help="[HOST:]PORT of the ovsdb-server") + parser.add_argument("rows", type=int, help="rows to seed") + parser.add_argument("blobsize", type=int, help="bytes per seeded row") + parser.add_argument("--throttle", type=int, default=0, metavar="BYTES", + help="read this many bytes a second (0: never read)") + parser.add_argument("--tls", nargs=3, default=None, + metavar=("PRIVKEY", "CERT", "CACERT"), + help="speak TLS, with these PEM files") + args = parser.parse_args(argv[1:]) + target, rows, blob = args.target, args.rows, args.blobsize + if args.tls: + TLS = tuple(args.tls) + + seed = connect(target) + ops = ["ordinals"] + ops += [{"op": "insert", "table": "ordinals", + "row": {"number": i, "name": "x" * blob}} for i in range(rows)] + reply = transact(seed, ops) + if reply.get("error"): + sys.exit("ovsdb-stall-client: seed failed: %s" % reply["error"]) + + stall = connect(target) + stall.sendall(json.dumps( + {"method": "monitor", + "params": ["ordinals", None, + {"ordinals": [{"columns": ["number", "name"]}]}], + "id": 1}).encode()) + + print("READY") + sys.stdout.flush() + if args.throttle: + drain(stall, args.throttle) + while True: + time.sleep(60) + + +if __name__ == '__main__': + main(sys.argv) diff --git a/tests/reconnect.at b/tests/reconnect.at index 5bca84351..7433ad5c5 100644 --- a/tests/reconnect.at +++ b/tests/reconnect.at @@ -1363,3 +1363,346 @@ run listening in LISTENING for 0 ms (0 ms backoff) ]) + +###################################################################### +dnl The guard belongs on the 1 ms retry alone. That retry is reached only once +dnl the interval has lapsed *and* no receive was attempted. ovsdb-server gates +dnl its receive on any backlog at all -- "if (!jsonrpc_session_get_backlog())" +dnl -- so a wedged session of its own never attempts one, never leaves that +dnl retry, and is neither probed nor dropped: the echo is not even queued for +dnl it. Every other jsonrpc_session user calls jsonrpc_session_recv() +dnl unconditionally, so for those the deadline is still reached with a queue +dnl standing. Guarding the whole probe-deadline branch instead would withhold +dnl the probe and the disconnect from them -- a raft leader would hold a +dnl follower that stopped taking data for ever -- and no ovsdb-server check +dnl would notice. +RECONNECT_CHECK([receive attempts still reach the probe with data queued], + [enable +run +connected + +# A caller that does not gate its receive on the backlog: raft, replication, +# ovsdb-client and the IDL all call jsonrpc_session_recv() unconditionally, +# so the receive attempt keeps landing while the queue stands. +queued-bytes 182346528 +advance 5000 +receive-attempted now +run + +# The probe is queued behind the backlog, so the peer never sees it and +# cannot answer. The disconnect runs off the timer rather than off the +# answer, so the session is still dropped at the ordinary deadline, which +# is what a peer that has stopped taking data gets today. +advance 5000 +receive-attempted now +run +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# A caller that does not gate its receive on the backlog: raft, replication, +# ovsdb-client and the IDL all call jsonrpc_session_recv() unconditionally, +# so the receive attempt keeps landing while the queue stands. +queued-bytes 182346528 +advance 5000 + +### t=6000 ### + in ACTIVE for 5000 ms (0 ms backoff) +receive-attempted now +run + should send probe + in IDLE for 0 ms (0 ms backoff) + +# The probe is queued behind the backlog, so the peer never sees it and +# cannot answer. The disconnect runs off the timer rather than off the +# answer, so the session is still dropped at the ordinary deadline, which +# is what a peer that has stopped taking data gets today. +advance 5000 + +### t=11000 ### + in IDLE for 5000 ms (0 ms backoff) +receive-attempted now +run + should disconnect +]) +###################################################################### +RECONNECT_CHECK([no wake-up while data is queued], + [enable + +# Connection succeeds. +run +connected + +# Data is queued for the peer that we could not send. +activity 1000 + +# Long past the probe interval the FSM asks for no wake-up at all, and +# nothing happens: the connection is neither probed nor disconnected. +advance 60000 +timeout +run +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) + +# Connection succeeds. +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# Data is queued for the peer that we could not send. +activity 1000 + +# Long past the probe interval the FSM asks for no wake-up at all, and +# nothing happens: the connection is neither probed nor disconnected. +advance 60000 + +### t=61000 ### + in ACTIVE for 60000 ms (0 ms backoff) +timeout + no timeout +run +]) + +###################################################################### +RECONNECT_CHECK([draining the queue restores probing], + [enable +run +connected + +# Queued: no wake-up, no probe. +activity 1000 +advance 10000 +run + +# The queue drains, so the ordinary probe interval applies again. +activity 0 +receive-attempted LLONG_MAX +timeout +run +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# Queued: no wake-up, no probe. +activity 1000 +advance 10000 + +### t=11000 ### + in ACTIVE for 10000 ms (0 ms backoff) +run + +# The queue drains, so the ordinary probe interval applies again. +activity 0 + created 1000, last activity 11000, last connected 1000 +receive-attempted LLONG_MAX +timeout + advance 5000 ms + +### t=16000 ### + in ACTIVE for 15000 ms (0 ms backoff) +run + should send probe + in IDLE for 0 ms (0 ms backoff) +]) + +###################################################################### +RECONNECT_CHECK([disconnect forgets queued data], + [enable +run +connected +activity 1000 + +# Disconnecting forgets the queued data. +disconnected +run +connected + +# So the ordinary probe interval applies again, and the millisecond retry +# past it is reached -- which a queue left over from the old connection +# would suppress. +timeout +timeout +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total +activity 1000 + +# Disconnecting forgets the queued data. +disconnected + in BACKOFF for 0 ms (1000 ms backoff) + 1 successful connections out of 1 attempts, seqno 2 + disconnected + disconnected at 1000 ms (0 ms ago) +run +connected + in ACTIVE for 0 ms (1000 ms backoff) + 2 successful connections out of 2 attempts, seqno 3 + connected + +# So the ordinary probe interval applies again, and the millisecond retry +# past it is reached -- which a queue left over from the old connection +# would suppress. +timeout + advance 5000 ms + +### t=6000 ### + in ACTIVE for 5000 ms (1000 ms backoff) +timeout + advance 1 ms + +### t=6001 ### + in ACTIVE for 5001 ms (1000 ms backoff) +]) + +dnl A peer that stops reading leaves the queue standing, so there is no +dnl activity left to report and the length has to be reported on its own. +dnl Remove the 'queued-bytes' line from the input below and the second +dnl timeout returns "advance 1 ms": the wake-up this suppresses. +RECONNECT_CHECK([no wake-up when data is queued after the last activity], + [enable + +# Connection succeeds. +run +connected + +# The queue drained just before the peer stalled, so the last activity the +# caller had to report carried an empty queue. +activity 0 + +# The peer stops reading. There is no further activity to report; the length +# of the standing queue is all the caller can still publish, and it must keep +# publishing it. +queued-bytes 182346528 + +# The FSM still sleeps to the probe deadline: that is an ordinary wake-up, +# not the 1 ms retry. Only once the deadline has lapsed with no receive +# attempted -- the retry's own case -- does it ask for no wake-up at all, +# because nothing a receive could do would settle anything while the caller +# cannot get data to this peer. +timeout +timeout +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) + +# Connection succeeds. +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# The queue drained just before the peer stalled, so the last activity the +# caller had to report carried an empty queue. +activity 0 + +# The peer stops reading. There is no further activity to report; the length +# of the standing queue is all the caller can still publish, and it must keep +# publishing it. +queued-bytes 182346528 + +# The FSM still sleeps to the probe deadline: that is an ordinary wake-up, +# not the 1 ms retry. Only once the deadline has lapsed with no receive +# attempted -- the retry's own case -- does it ask for no wake-up at all, +# because nothing a receive could do would settle anything while the caller +# cannot get data to this peer. +timeout + advance 5000 ms + +### t=6000 ### + in ACTIVE for 5000 ms (0 ms backoff) +timeout + no timeout +]) + +dnl The same 1 ms wake-up is reachable from IDLE: a quiet connection is probed, +dnl and only then does the peer stop taking data. The guard belongs in both +dnl states, not only in ACTIVE. The probe deadline itself is still +dnl reported, so a peer that is being received from is still dropped on +dnl time. +RECONNECT_CHECK([no wake-up while data is queued in IDLE], + [enable +run +connected + +# A quiet connection is probed, so the FSM is in IDLE. +timeout +receive-attempted now +run + +# Only now does the peer stop taking data. +queued-bytes 182346528 +timeout +timeout +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# A quiet connection is probed, so the FSM is in IDLE. +timeout + advance 5000 ms + +### t=6000 ### + in ACTIVE for 5000 ms (0 ms backoff) +receive-attempted now +run + should send probe + in IDLE for 0 ms (0 ms backoff) + +# Only now does the peer stop taking data. +queued-bytes 182346528 +timeout + advance 5000 ms + +### t=11000 ### + in IDLE for 5000 ms (0 ms backoff) +timeout + no timeout +]) diff --git a/tests/test-reconnect.c b/tests/test-reconnect.c index c84bb1cdb..26d522624 100644 --- a/tests/test-reconnect.c +++ b/tests/test-reconnect.c @@ -147,11 +147,26 @@ do_connected(struct ovs_cmdl_context *ctx OVS_UNUSED) } static void -do_activity(struct ovs_cmdl_context *ctx OVS_UNUSED) +do_set_probe_interval(struct ovs_cmdl_context *ctx) { + reconnect_set_probe_interval(reconnect, atoi(ctx->argv[1])); +} + +static void +do_activity(struct ovs_cmdl_context *ctx) +{ + if (ctx->argc > 1) { + reconnect_set_queued_bytes(reconnect, atoi(ctx->argv[1])); + } reconnect_activity(reconnect, now); } +static void +do_queued_bytes(struct ovs_cmdl_context *ctx) +{ + reconnect_set_queued_bytes(reconnect, atoi(ctx->argv[1])); +} + static void do_run(struct ovs_cmdl_context *ctx) { @@ -297,7 +312,9 @@ static const struct ovs_cmdl_command all_commands[] = { { "connecting", NULL, 0, 0, do_connecting, OVS_RO }, { "connect-failed", NULL, 0, 1, do_connect_failed, OVS_RO }, { "connected", NULL, 0, 0, do_connected, OVS_RO }, - { "activity", NULL, 0, 0, do_activity, OVS_RO }, + { "activity", NULL, 0, 1, do_activity, OVS_RO }, + { "queued-bytes", NULL, 1, 1, do_queued_bytes, OVS_RO }, + { "set-probe-interval", NULL, 1, 1, do_set_probe_interval, OVS_RO }, { "run", NULL, 0, 1, do_run, OVS_RO }, { "advance", NULL, 1, 1, do_advance, OVS_RO }, { "timeout", NULL, 0, 0, do_timeout, OVS_RO }, diff --git a/tests/test-reconnect.py b/tests/test-reconnect.py index cea48eb52..797a50ac2 100644 --- a/tests/test-reconnect.py +++ b/tests/test-reconnect.py @@ -61,10 +61,20 @@ def do_connected(_): r.connected(now) -def do_activity(_): +def do_set_probe_interval(arg): + r.set_probe_interval(int(arg)) + + +def do_activity(arg): + if arg is not None: + r.set_queued_bytes(int(arg)) r.activity(now) +def do_queued_bytes(arg): + r.set_queued_bytes(int(arg)) + + def do_run(arg): global now if arg is not None: @@ -181,6 +191,8 @@ def main(): "connect-failed": do_connect_failed, "connected": do_connected, "activity": do_activity, + "queued-bytes": do_queued_bytes, + "set-probe-interval": do_set_probe_interval, "run": do_run, "advance": do_advance, "timeout": do_timeout, From patchwork Wed Sep 2 22:07:43 2026 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Aeliton Silva (ESP - MGC NETP.SDN)" X-Patchwork-Id: 2297062 X-Patchwork-Delegate: i.maximets@samsung.com Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@legolas.ozlabs.org Authentication-Results: legolas.ozlabs.org; dkim=fail reason="signature verification failed" (2048-bit key; unprotected) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=ZukFbHh9; dkim-atps=neutral Authentication-Results: legolas.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org (client-ip=2605:bc80:3010::137; helo=smtp4.osuosl.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver=patchwork.ozlabs.org) Received: from smtp4.osuosl.org (smtp4.osuosl.org [IPv6:2605:bc80:3010::137]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange x25519 server-signature ECDSA (secp384r1) server-digest SHA384) (No client certificate requested) by legolas.ozlabs.org (Postfix) with ESMTPS id 4hZxgT4HR2z1y03 for ; Thu, 03 Sep 2026 08:08:05 +1000 (AEST) Received: from localhost (localhost [127.0.0.1]) by smtp4.osuosl.org (Postfix) with ESMTP id ADBD840A5B; Wed, 2 Sep 2026 22:08:03 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp4.osuosl.org ([127.0.0.1]) by localhost (smtp4.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id LltDQ9hHSdYV; Wed, 2 Sep 2026 22:08:01 +0000 (UTC) ARC-Filter: OpenARC Filter v1.3.0 smtp4.osuosl.org AE6B640A4D Authentication-Results: smtp4.osuosl.org; arc=fail smtp.remote-ip="2605:bc80:3010:104::8cd3:938" ARC-Seal: i=2; d=osuosl.org; s=arc; a=rsa-sha256; cv=fail; t=1788386881; b=Lab4slq2yfdzKYn0JmoBXhwZ8mLCqof5o7/SxT1MMS4YFBt3og1QQv444D5Nt1WQT8uO Zmd+qPAwcU4xepgvFIE7BufwnWgnSkVDl+7LXfCx5/zalrhPM0Ys4NakCA1f7iwuQRpVN E8s6lYEjpQrzOmyVAAL3Pm5JHZdHFV96zbrlFC2vm+amrVOSEG1cZ8BVD3ZO3CoajslRQ UgbfjYhYFQ8Jqwe+LLEK2umbsSgy8Ngt+TlxxyhrKrzFgpSXcOFRr1NSibimPNUL6WLJi NYvNMvlnaebfanZmYHbEk2NjaFicXBAoYhn5lBTS5yWvFmrxOo64eu5I2cy02nYpZtg== ARC-Message-Signature: i=2; d=osuosl.org; s=arc; a=rsa-sha256; c=relaxed/relaxed; t=1788386881; h=X-Comment:Received:X-Original-To:Delivered-To:Received:Received: X-Virus-Scanned:X-Spam-Flag:X-Spam-Score:X-Spam-Level:X-Spam-Status: Received:ARC-Filter:Received-SPF:Received:Received:DKIM-Signature: X-Google-DKIM-Signature:X-Gm-Message-State:X-Gm-Gg:X-Received: Received:From:To:Date:Message-ID:X-Mailer:In-Reply-To:References: MIME-Version:Subject:X-BeenThere:X-Mailman-Version:Precedence:List-Id: List-Unsubscribe:List-Archive:List-Post:List-Help:List-Subscribe: Content-Type:Content-Transfer-Encoding:Errors-To:Sender; bh=6egLUEsFKRZnQ4FEZLWVHhT87OddfjjpwkDrt/7Wulk=; b=lsFiMSK1kSnvG6+CjJJhiwkPgOSMlXxOB5E51+2GjhhDlyav4P8QU5HYgp56BKMxh5q1 PUHXmu9GV9/13oryCbDzS7KKdEvs5/MjMvj59jHKpJ+n9kNS+nPlTfIXbCJNFHqlYXP0D uTwUeWI1C2sANR9oJmwCSr7KOSUcNeED5Dm0eXkHqqAVI94fmSCe+/G4Yc1t87SElqKOm Ar2YLAmKGkWwhnNxsk/tnmiYKPCqir0eFaNnYvRhFoMyUq2rKfgmDFDgE18nVqlBFK2sd cAYa84qjMsInJy3VSW3dzjGjmj7355jOMfdbtr7Kekwb26gTtrhO7f09o7zCWGKEQMQ== ARC-Authentication-Results: i=2; smtp4.osuosl.org; dkim=fail reason="signature verification failed" header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=ZukFbHh9; arc=fail smtp.remote-ip="2605:bc80:3010:104::8cd3:938" X-Comment: SPF check N/A for local connections - client-ip=2605:bc80:3010:104::8cd3:938; helo=lists.linuxfoundation.org; envelope-from=ovs-dev-bounces@openvswitch.org; receiver= Authentication-Results: smtp4.osuosl.org; dkim=fail reason="signature verification failed" (2048-bit key) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=ZukFbHh9 Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [IPv6:2605:bc80:3010:104::8cd3:938]) by smtp4.osuosl.org (Postfix) with ESMTPS id AE6B640A4D; Wed, 2 Sep 2026 22:08:01 +0000 (UTC) Received: from lf-lists.osuosl.org (localhost [127.0.0.1]) by lists.linuxfoundation.org (Postfix) with ESMTP id 7649FC0419; Wed, 2 Sep 2026 22:08:01 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@lists.linuxfoundation.org Received: from smtp1.osuosl.org (smtp1.osuosl.org [IPv6:2605:bc80:3010::138]) by lists.linuxfoundation.org (Postfix) with ESMTP id BB045C041A for ; Wed, 2 Sep 2026 22:08:00 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by smtp1.osuosl.org (Postfix) with ESMTP id A4F2D80E6B for ; Wed, 2 Sep 2026 22:08:00 +0000 (UTC) X-Virus-Scanned: amavis at osuosl.org Received: from smtp1.osuosl.org ([127.0.0.1]) by localhost (smtp1.osuosl.org [127.0.0.1]) (amavis, port 10024) with ESMTP id rjoqL7LixPxk for ; Wed, 2 Sep 2026 22:07:59 +0000 (UTC) ARC-Filter: OpenARC Filter v1.3.0 smtp1.osuosl.org 334FB80E1C Authentication-Results: smtp1.osuosl.org; arc=none smtp.remote-ip="2607:f8b0:4864:20::112c" ARC-Seal: i=1; d=osuosl.org; s=arc; a=rsa-sha256; cv=none; t=1788386879; b=TZT0k2rzFhAFofin05PfZkgsyXLt8Iy0uriUSSOHeuSRjJ+0Ll1gth8EHROeOWhk8t/G 7ZR1Or9P2nUWA7C7D0PHK0QEpZZwwOkAGIbMkxB5lj/xe1h5KlhGVAKag8C5jJoF8FGep biiEUws33RxwJkowHt+VbLnlriZHmhOV8AaEtliwUcn+q/5LYrL3pMPVTWbBZ8Nat4/E2 HAf3OYIRWiPtGrHYp4mBnRq50gk99gBBpFZx4XkQhtOgJ2GCVw3YIG4+NAAoRQDhlbYwD mm9RhTCteYF7eBy30xGxuNta7RhPK7RNe98r1ogyJFp/G3SdwIUu+x9q1fUSZUdatiA== ARC-Message-Signature: i=1; d=osuosl.org; s=arc; a=rsa-sha256; c=relaxed/relaxed; t=1788386879; h=Received-SPF:Received:DKIM-Signature:X-Google-DKIM-Signature: X-Gm-Message-State:X-Gm-Gg:X-Received:Received:From:To:Cc:Subject: Date:Message-ID:X-Mailer:In-Reply-To:References:MIME-Version: Content-Transfer-Encoding:Content-Type; bh=VUzBxPmHuqttknD6wxVMRYhG1ds8i0YQGfDiXKa/Xao=; b=hNAaUjHQ4XG6j/zxIGf5O3gap2D0KxCArcE12jgkM3oo71gm0uGrbQDk3mjV3oNVwIFV i8zqNv/vgM7lI70/P821+JfCW5Z+lzu8aJh+HV2+2nokFeyzBXjygx1ZbRvPgEw6Z3PJh kDXnxWAwJGPsg2s9Sx0k5Ex1uVJdZXJ6W6P7u++YrU+Wurx4VH5gnM+MhTvWmgAg2mNDG wIIKgALSHrYo5o9W5rOwo+Exl+J0VlHOy9qFX7c/BvJo7j5qG5w0mNmBPDMkyrxNHNu9C 25KSsN2MFjbuRx0VHVLK0CcGA8chH7iXVwoKGTX/zk71j5hjWGfLI5Ls2AVeHy0TKOA== ARC-Authentication-Results: i=1; smtp1.osuosl.org; dmarc=pass header.from=magalu.cloud; dkim=pass header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=ZukFbHh9; arc=none smtp.remote-ip="2607:f8b0:4864:20::112c" Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=2607:f8b0:4864:20::112c; helo=mail-yw1-x112c.google.com; envelope-from=aeliton.silva@magalu.cloud; receiver= Authentication-Results: smtp1.osuosl.org; dmarc=pass (p=none dis=none) header.from=magalu.cloud Authentication-Results: smtp1.osuosl.org; dkim=pass (2048-bit key) header.d=magalu-cloud.20251104.gappssmtp.com header.i=@magalu-cloud.20251104.gappssmtp.com header.a=rsa-sha256 header.s=20251104 header.b=ZukFbHh9 Received: from mail-yw1-x112c.google.com (mail-yw1-x112c.google.com [IPv6:2607:f8b0:4864:20::112c]) by smtp1.osuosl.org (Postfix) with ESMTPS id 334FB80E1C for ; Wed, 2 Sep 2026 22:07:58 +0000 (UTC) Received: by mail-yw1-x112c.google.com with SMTP id 00721157ae682-7dbcb505578so21708117b3.3 for ; Wed, 02 Sep 2026 15:07:58 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=magalu-cloud.20251104.gappssmtp.com; s=20251104; t=1788386877; x=1788991677; darn=openvswitch.org; h=content-type:content-transfer-encoding:mime-version:references :in-reply-to:message-id:date:subject:cc:to:from:from:to:cc:subject :date:message-id:reply-to:content-type; bh=VUzBxPmHuqttknD6wxVMRYhG1ds8i0YQGfDiXKa/Xao=; b=ZukFbHh9uFk7+p9giptTtFYbDN36reUhVY83ZmHTjDyMpryDtWwARW+UlFpOtfnf/z YY+DBu+imbXylXoVo3U6ajOMClXaHkDnMu10z9HSk58GPGmiOBWl4LSl6qWqvvEEQlRE T6LFnhhKWQ2Zqs+LMle/qiWxbEZJtOT/Xg+UzzIBH4Oy1vgkT98Lwvwld/Dnjqy3EOFd TOQ4bvxtVDynnSc45eM1n5A3eMz0Ril6Gjs2tWKRcdBihfnGfEqWZAiNVxSerkUTn+h5 sU2s5lHYPLCgsOlubjXdZ4A9SxbkRsgN7R03jhU7wEdK43WcoCtEt7hY+2DwDVgwJS2q jFrg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20251104; t=1788386877; x=1788991677; h=content-type:content-transfer-encoding:mime-version:references :in-reply-to:message-id:date:subject:cc:to:from:x-gm-gg :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to :content-type; bh=VUzBxPmHuqttknD6wxVMRYhG1ds8i0YQGfDiXKa/Xao=; b=AYDJMhryxxxeAp81UlaW6meu6vO8PU06EyrECqfZkkZMr24HIDMZCanrtVKr5Ith6T k0yq5ZMMYv/ph2KBA4DwCgActA/65yAb/GCSjqgGZ0q3VqJIZnonmcBaQdMBXpDsy+jW rwnDGwKrXFm8X5wEBxzZAueL2okMSkBASshvOMU25F2n+kQf9f7UpI7vjMMXnElVJNDA vE5UyPXJolj2iKCoRurnhhiV600DJ348Te+XajW25nc1m7EMLDpMgYhc190nGd47/rPc xUyBxcF5cRHbcYU9rW3qKJXOOvV6oGFLshhLfsxvao7jzzsqYycXxozCHlTzvSQ3wO3y yNAA== X-Gm-Message-State: AFuF++lnVzAK3FYHPF6lXXWKz6Ve7ZxmqRAv+OOcwn7HDxIfZvYrYl5d CqnSX4hbUpJ97eZPKZSrxYWDUH8UseJ/QlZqAUxJmZjeJYC4w5VOTY+YqRAnXx7MsR73AV4pJAj Eo55UB67AYjty6vOTdrVHgLzeL71lEabJD3jUWHvmO45fa1GPbTkw1FyIMzaOxnU= X-Gm-Gg: AYBFou2fzarFWerR83HCjFFlEL7GCcGMRapuRooOfrFKFaG2WLlU0ycIFXk0YPYXu8Q VlhYyDfvCrTmuvZzqJvWXGNYGFYvVFYMAersxJaLA9EFP9tSUjGg2Ecl0FpQpsjEAkkyrdonRAF rFw736BLzB86X1ZMCtNT6ZYPYzl8nzeUVnjjJiTEP9EtvGhwa4WDZpfvu+GvMLrJnvfRxSRh36H WHpa2qVEpgHOuZ2/ORcckVWjWkjJwbtQUc5pzLUO8aoo6KM56KO0UrGSLku83YlahdQQfQqzhTM hxt1m/CiGjwmPM3ZGJ35bq+bV6f5+k5kuExTWtgaKTa5fH3ujlZc/oChqgOTImaa3+3BynyVukD h4Or23MEmDM0mBf7nfFK+3eQzw6MXtrLBBwy7gJXyboQxOBEsZ3UZpqdiojP0aXc64XpBXa1iF5 sx7CSuPQypzDO/8fldSihWHavtcRGel8MiNPF5CR5LrKui/mq6WkC0IrzMh28y/HpgSe8W098eI vE= X-Received: by 2002:a05:690c:ed6:b0:7ba:f690:70be with SMTP id 00721157ae682-86c4df23cccmr41386687b3.7.1788386876661; Wed, 02 Sep 2026 15:07:56 -0700 (PDT) Received: from WNLEC-7T3RN34.lan ([45.165.21.178]) by smtp.gmail.com with ESMTPSA id 00721157ae682-86c18ac450csm27279497b3.40.2026.09.02.15.07.54 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 02 Sep 2026 15:07:55 -0700 (PDT) From: "Aeliton G. Silva" To: dev@openvswitch.org Date: Wed, 2 Sep 2026 19:07:43 -0300 Message-ID: <20260902220743.4157943-2-aeliton.silva@magalu.cloud> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20260902220743.4157943-1-aeliton.silva@magalu.cloud> References: <20260902220743.4157943-1-aeliton.silva@magalu.cloud> MIME-Version: 1.0 Subject: [ovs-dev] [PATCH v2 2/2] reconnect: Terminate a connection that stops taking data. X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.30 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: ovs-dev-bounces@openvswitch.org Sender: "dev" Patch 1/2 of this patchset removed the pin's most visible symptom: hundreds of poll passes a second. A peer that has stopped reading is now entirely silent -- still never probed, never disconnected, nothing logged, and no longer costing the CPU that used to give it away. Let the ordinary probe and timeout run for such a session instead. A non-backlogged session that does not answer its probes is dropped after two probe intervals; a backlogged session that is not seen reading for the same two intervals is now treated the same way, and says so through the existing "no response to inactivity probe" message, extended to name the bytes still queued. What matters is not how fast a peer reads but whether the server can see it reading. All the server sees is its own queue shrinking, and that happens only when the socket send buffer has room -- which the peer controls, by acknowledging data already sent and by reopening its receive window as it reads. A peer that moves the queue within the interval is unaffected, however slowly it consumes. Testing. Multiple runs of the test client from patch 1/2 (also applied), reading at different rates. At the 5 s TCP default: rate unpatched patched 0 kB/s never t+11 s / 5.3 MB 4 kB/s t+1348 s / 0 t+27 s / 5.2 MB 20 kB/s t+278 s / 0 t+278 s / 0 (dropped at / backlog at drop) Only the first two rows change, and they change because the queue had not moved for two probe intervals while megabytes still stood. The third is a control: at 20 kB/s the queue moves again well inside two probe intervals, so it drains normally. Those drains are also why the unpatched column is not a liveness verdict -- the test client never answers an inactivity probe, so once it has drained it looks idle to either build. A client that is expected to be slow can still be left alone by increasing the inactivity_probe duration, giving it more time to be seen reading: at 10000 ms the 4 kB/s reader is still dropped, at t+37 s, and at 20000 ms it survives. Considered, measured and deemed not viable: ungating ovsdb-server's receive by removing "if (!jsonrpc_session_get_backlog(s->js))", which suppresses it while any backlog stands. It drops a stalled session too, by letting the receive attempt land, but that gate also holds back ovsdb_jsonrpc_monitor_flush_all(), which is what lets updates to a backlogged monitor combine instead of being sent one by one; and it changes ovsdb-server to fix a timer that lives in the FSM. Signed-off-by: Aeliton G. Silva Assisted-by: Claude Opus 5, Claude Code --- Notes: v2: - Commit message: test details measured on both builds; dropped an incorrect claim about raft, which never gates its receive and so already reaches the timeout today. - Tests: the check that a reader is kept now drains every three probe intervals. v1 drained every 4 s, inside a single interval, so it could not have caught a reader dropped for reading slowly. - Rebased on patch 1/2's queued-bytes reporting, so the hunks differ from v1; the resulting reconnect_deadline__ does not. lib/reconnect.c | 32 +++++--- python/ovs/reconnect.py | 23 ++++-- tests/reconnect.at | 166 ++++++++++++++++++++++++++++++++-------- 3 files changed, 170 insertions(+), 51 deletions(-) diff --git a/lib/reconnect.c b/lib/reconnect.c index 87dc7715d..96957dab0 100644 --- a/lib/reconnect.c +++ b/lib/reconnect.c @@ -508,9 +508,11 @@ reconnect_activity(struct reconnect *fsm, long long int now) } /* Tell 'fsm' how much data is currently queued for the peer and has not been - * sent. While it is nonzero the FSM does not ask to be woken up to attempt a - * receive: the caller evidently cannot get data to this peer, so no receive it - * makes can settle anything. */ + * sent. While it is nonzero the probe interval is allowed to expire on its + * own schedule rather than asking for a fast wake-up to attempt a receive: + * the caller evidently cannot get data to this peer, so no receive it makes + * can settle anything, and the ordinary probe and timeout should run their + * course. */ void reconnect_set_queued_bytes(struct reconnect *fsm, size_t queued_bytes) { @@ -571,13 +573,14 @@ reconnect_deadline__(const struct reconnect *fsm, long long int now) if (fsm->probe_interval) { long long int base = MAX(fsm->last_activity, fsm->state_entered); long long int expiration = base + fsm->probe_interval; - if (now < expiration || fsm->last_receive_attempt >= expiration) { + if (now < expiration || fsm->last_receive_attempt >= expiration + || fsm->queued_bytes) { /* We still have time before the expiration or the time has * already passed and there was no activity. In the first case * we need to wait for the expiration, in the second - we're * already past the deadline. */ return expiration; - } else if (!fsm->queued_bytes) { + } else { /* Time has already passed, but we didn't attempt to receive * anything. We need to wake up and try to receive even if * nothing is pending, so we can update the expiration time or @@ -590,9 +593,10 @@ reconnect_deadline__(const struct reconnect *fsm, long long int now) case S_IDLE: if (fsm->probe_interval) { long long int expiration = fsm->state_entered + fsm->probe_interval; - if (now < expiration || fsm->last_receive_attempt >= expiration) { + if (now < expiration || fsm->last_receive_attempt >= expiration + || fsm->queued_bytes) { return expiration; - } else if (!fsm->queued_bytes) { + } else { return now + 1; } } @@ -662,9 +666,17 @@ reconnect_run(struct reconnect *fsm, long long int now) return RECONNECT_PROBE; case S_IDLE: - VLOG_ERR("%s: no response to inactivity probe after %.3g " - "seconds, disconnecting", - fsm->name, (now - fsm->state_entered) / 1000.0); + if (fsm->queued_bytes) { + VLOG_ERR("%s: no response to inactivity probe after %.3g " + "seconds, with %"PRIuSIZE" bytes still queued for " + "the peer, disconnecting", fsm->name, + (now - fsm->state_entered) / 1000.0, + fsm->queued_bytes); + } else { + VLOG_ERR("%s: no response to inactivity probe after %.3g " + "seconds, disconnecting", + fsm->name, (now - fsm->state_entered) / 1000.0); + } return RECONNECT_DISCONNECT; case S_RECONNECT: diff --git a/python/ovs/reconnect.py b/python/ovs/reconnect.py index 38b2f7e32..ba7bfd58a 100644 --- a/python/ovs/reconnect.py +++ b/python/ovs/reconnect.py @@ -98,13 +98,14 @@ class Reconnect(object): expiration = base + fsm.probe_interval if (now < expiration or fsm.last_receive_attempt is None or - fsm.last_receive_attempt >= expiration): + fsm.last_receive_attempt >= expiration or + fsm.queued_bytes): # We still have time before the expiration or the time has # already passed and there was no activity. In the first # case we need to wait for the expiration, in the second - # we're already past the deadline. */ return expiration - elif not fsm.queued_bytes: + else: # Time has already passed, but we didn't attempt to receive # anything. We need to wake up and try to receive even if # nothing is pending, so we can update the expiration time @@ -130,17 +131,25 @@ class Reconnect(object): expiration = fsm.state_entered + fsm.probe_interval if (now < expiration or fsm.last_receive_attempt is None or - fsm.last_receive_attempt >= expiration): + fsm.last_receive_attempt >= expiration or + fsm.queued_bytes): return expiration - elif not fsm.queued_bytes: + else: return now + 1 return None @staticmethod def run(fsm, now): - vlog.err("%s: no response to inactivity probe after %.3g " - "seconds, disconnecting" - % (fsm.name, (now - fsm.state_entered) / 1000.0)) + if fsm.queued_bytes: + vlog.err("%s: no response to inactivity probe after %.3g " + "seconds, with %d bytes still queued for the peer, " + "disconnecting" + % (fsm.name, (now - fsm.state_entered) / 1000.0, + fsm.queued_bytes)) + else: + vlog.err("%s: no response to inactivity probe after %.3g " + "seconds, disconnecting" + % (fsm.name, (now - fsm.state_entered) / 1000.0)) return DISCONNECT class Reconnect(object): diff --git a/tests/reconnect.at b/tests/reconnect.at index 7433ad5c5..e65d5cc50 100644 --- a/tests/reconnect.at +++ b/tests/reconnect.at @@ -1368,11 +1368,10 @@ listening dnl The guard belongs on the 1 ms retry alone. That retry is reached only once dnl the interval has lapsed *and* no receive was attempted. ovsdb-server gates dnl its receive on any backlog at all -- "if (!jsonrpc_session_get_backlog())" -dnl -- so a wedged session of its own never attempts one, never leaves that -dnl retry, and is neither probed nor dropped: the echo is not even queued for -dnl it. Every other jsonrpc_session user calls jsonrpc_session_recv() -dnl unconditionally, so for those the deadline is still reached with a queue -dnl standing. Guarding the whole probe-deadline branch instead would withhold +dnl -- so a wedged session of its own never attempts one and cannot answer the +dnl probe, and runs on to the disconnect. Every other jsonrpc_session user +dnl calls jsonrpc_session_recv() unconditionally, so for those an answer can +dnl still arrive and reset the deadline. Guarding the whole probe-deadline branch instead would withhold dnl the probe and the disconnect from them -- a raft leader would hold a dnl follower that stopped taking data for ever -- and no ovsdb-server check dnl would notice. @@ -1435,7 +1434,7 @@ run should disconnect ]) ###################################################################### -RECONNECT_CHECK([no wake-up while data is queued], +RECONNECT_CHECK([peer with queued data is dropped], [enable # Connection succeeds. @@ -1445,9 +1444,12 @@ connected # Data is queued for the peer that we could not send. activity 1000 -# Long past the probe interval the FSM asks for no wake-up at all, and -# nothing happens: the connection is neither probed nor disconnected. -advance 60000 +# Past the probe interval the connection is probed, on the ordinary +# schedule rather than after a fast wake-up. +timeout +run + +# And a probe interval later, with nothing taken, it is given up on. timeout run ], @@ -1468,15 +1470,25 @@ connected # Data is queued for the peer that we could not send. activity 1000 -# Long past the probe interval the FSM asks for no wake-up at all, and -# nothing happens: the connection is neither probed nor disconnected. -advance 60000 +# Past the probe interval the connection is probed, on the ordinary +# schedule rather than after a fast wake-up. +timeout + advance 5000 ms + +### t=6000 ### + in ACTIVE for 5000 ms (0 ms backoff) +run + should send probe + in IDLE for 0 ms (0 ms backoff) -### t=61000 ### - in ACTIVE for 60000 ms (0 ms backoff) +# And a probe interval later, with nothing taken, it is given up on. timeout - no timeout + advance 5000 ms + +### t=11000 ### + in IDLE for 5000 ms (0 ms backoff) run + should disconnect ]) ###################################################################### @@ -1485,7 +1497,7 @@ RECONNECT_CHECK([draining the queue restores probing], run connected -# Queued: no wake-up, no probe. +# Queued and nothing moving: probed on the ordinary schedule. activity 1000 advance 10000 run @@ -1508,23 +1520,26 @@ connected connected last connected 0 ms ago, connected 0 ms total -# Queued: no wake-up, no probe. +# Queued and nothing moving: probed on the ordinary schedule. activity 1000 advance 10000 ### t=11000 ### in ACTIVE for 10000 ms (0 ms backoff) run + should send probe + in IDLE for 0 ms (0 ms backoff) # The queue drains, so the ordinary probe interval applies again. activity 0 + in ACTIVE for 0 ms (0 ms backoff) created 1000, last activity 11000, last connected 1000 receive-attempted LLONG_MAX timeout advance 5000 ms ### t=16000 ### - in ACTIVE for 15000 ms (0 ms backoff) + in ACTIVE for 5000 ms (0 ms backoff) run should send probe in IDLE for 0 ms (0 ms backoff) @@ -1592,7 +1607,7 @@ dnl A peer that stops reading leaves the queue standing, so there is no dnl activity left to report and the length has to be reported on its own. dnl Remove the 'queued-bytes' line from the input below and the second dnl timeout returns "advance 1 ms": the wake-up this suppresses. -RECONNECT_CHECK([no wake-up when data is queued after the last activity], +RECONNECT_CHECK([the probe deadline is kept when data is queued after the last activity], [enable # Connection succeeds. @@ -1608,13 +1623,11 @@ activity 0 # publishing it. queued-bytes 182346528 -# The FSM still sleeps to the probe deadline: that is an ordinary wake-up, -# not the 1 ms retry. Only once the deadline has lapsed with no receive -# attempted -- the retry's own case -- does it ask for no wake-up at all, -# because nothing a receive could do would settle anything while the caller -# cannot get data to this peer. +# The probe deadline is still reported, so the connection is probed on the +# ordinary schedule rather than after the 1 ms retry. timeout timeout +run ], [### t=1000 ### enable @@ -1639,18 +1652,18 @@ activity 0 # publishing it. queued-bytes 182346528 -# The FSM still sleeps to the probe deadline: that is an ordinary wake-up, -# not the 1 ms retry. Only once the deadline has lapsed with no receive -# attempted -- the retry's own case -- does it ask for no wake-up at all, -# because nothing a receive could do would settle anything while the caller -# cannot get data to this peer. +# The probe deadline is still reported, so the connection is probed on the +# ordinary schedule rather than after the 1 ms retry. timeout advance 5000 ms ### t=6000 ### in ACTIVE for 5000 ms (0 ms backoff) timeout - no timeout + advance 0 ms +run + should send probe + in IDLE for 0 ms (0 ms backoff) ]) dnl The same 1 ms wake-up is reachable from IDLE: a quiet connection is probed, @@ -1658,7 +1671,7 @@ dnl and only then does the peer stop taking data. The guard belongs in both dnl states, not only in ACTIVE. The probe deadline itself is still dnl reported, so a peer that is being received from is still dropped on dnl time. -RECONNECT_CHECK([no wake-up while data is queued in IDLE], +RECONNECT_CHECK([the probe deadline is kept while data is queued in IDLE], [enable run connected @@ -1668,10 +1681,12 @@ timeout receive-attempted now run -# Only now does the peer stop taking data. +# Only now does the peer stop taking data. The deadline is still reported, so +# the disconnect runs on the ordinary schedule. queued-bytes 182346528 timeout timeout +run ], [### t=1000 ### enable @@ -1696,7 +1711,8 @@ run should send probe in IDLE for 0 ms (0 ms backoff) -# Only now does the peer stop taking data. +# Only now does the peer stop taking data. The deadline is still reported, so +# the disconnect runs on the ordinary schedule. queued-bytes 182346528 timeout advance 5000 ms @@ -1704,5 +1720,87 @@ timeout ### t=11000 ### in IDLE for 5000 ms (0 ms backoff) timeout - no timeout + advance 0 ms +run + should disconnect +]) +###################################################################### +dnl The property commit 633f72479 restored when it reverted disconnect-on- +dnl backlog: a slow reader is not a dead one. All the server can see is its +dnl own queue shrinking, and a receiver defers window updates until a +dnl worthwhile part of its buffer is free, so a healthy slow reader moves the +dnl queue in bursts that are far apart in time. Every burst is activity, and +dnl activity returns the FSM to ACTIVE from IDLE, so a peer that is still +dnl reading survives being probed however far behind it has fallen. +RECONNECT_CHECK([a queue that keeps moving is never given up on], + [enable +run +connected + +# The peer is reading, just slowly: the queue shrinks once every three probe +# intervals, so the session is probed each time -- but every shrink is +# activity, which returns the FSM to ACTIVE, so it is never given up on. +queued-bytes 182346528 +advance 15000 +run +activity 182300000 +advance 15000 +run +activity 182200000 +advance 15000 +run +activity 182100000 +timeout +], + [### t=1000 ### +enable + in BACKOFF for 0 ms (0 ms backoff) +run + should connect +connected + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 1000, last connected 1000 + 1 successful connections out of 1 attempts, seqno 1 + connected + last connected 0 ms ago, connected 0 ms total + +# The peer is reading, just slowly: the queue shrinks once every three probe +# intervals, so the session is probed each time -- but every shrink is +# activity, which returns the FSM to ACTIVE, so it is never given up on. +queued-bytes 182346528 +advance 15000 + +### t=16000 ### + in ACTIVE for 15000 ms (0 ms backoff) +run + should send probe + in IDLE for 0 ms (0 ms backoff) +activity 182300000 + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 16000, last connected 1000 +advance 15000 + +### t=31000 ### + in ACTIVE for 15000 ms (0 ms backoff) +run + should send probe + in IDLE for 0 ms (0 ms backoff) +activity 182200000 + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 31000, last connected 1000 +advance 15000 + +### t=46000 ### + in ACTIVE for 15000 ms (0 ms backoff) +run + should send probe + in IDLE for 0 ms (0 ms backoff) +activity 182100000 + in ACTIVE for 0 ms (0 ms backoff) + created 1000, last activity 46000, last connected 1000 +timeout + advance 5000 ms + +### t=51000 ### + in ACTIVE for 5000 ms (0 ms backoff) ])