mirror of
https://gitcode.com/JianFeeeee/webui4frpc.git
synced 2026-10-06 07:27:18 +00:00
fix(cluster): 停用的转发会在重启后自己复活 + 令牌轮转日志刷屏
从线上三节点(192.168.2.{30,106,60})的日志里挖出四个问题,本轮修三个。
## 1. 停用的转发会复活(功能性缺陷,实测仍在发生)
线上现象:`minecraft` 在 store 里 disabled=1,worker 却仍在跑,今天
09:46 还在刷 `connect to local service [192.168.2.60:25565]: connection
refused` —— 对着一个用户刻意没启的本地服务死刷。同时三台 logs 里躺着
13956 / 3769 条 `proxy [x] already exists`,每 33 秒一轮。
四处叠加导致:
- stopForward 先读 link,再 SetLinkDisabled(true),然后把**改之前**的
副本交给 RevokeTask ⇒ published task 带 disabled=false(实测 id/flag
都对不上:topology 里 link.id=223,store 里同一行是 199)
- ClaimFn **无条件** SetLinkDisabled(...,false)。原意是"重新认领时清掉
停用标记",但启动 reconcile 只要 worker 不在就重新 Claim ⇒ 每次重启
都是"先清标记再起 worker"
- RevokeFn 停了 worker 却**没删 topology 条目**,条目活过 worker
- 于是下次重启 reconcile 看到"owned 但 worker 不在"→ 再次 Claim → 死循环
修法(把 disabled 的所有权交回两个用户动作):
- Claim **只读** disabled 决定要不要起 worker;为 true 时连 topology
条目一起摘掉,绝不复活
- 启动 reconcile 先按 store 跳过 disabled 的条目(省掉无谓的
claim→skip 往返)
- RevokeFn 除停 worker 外,同时 RemoveTopologyEntry —— 撤销必须是
完整退役,不能只是"停一下"
- stopForward 把 Disabled=true 随 task 发布出去,让持有该转发的节点
即使本地 store 行陈旧也能判断这次停用是用户主动的
## 2. 令牌轮转日志零信息量却占满磁盘
每轮固定 3 行(OnToken cycle=N / forward cycle=N / token-send -> 200),
2 轮/秒,实测本机 **355 行/分钟、7 天 357 万行**,把真事件全淹了。
同一份信息(cycle / lastSync / roundDelayMs / 成员存活)本来就能从
GET /api/manager/cluster/ring 结构化拿到。
加 W4F_DEBUG 开关(沿用项目既有 W4F_ 前缀约定):稳态三行降级为 debug、
默认关闭;**失败路径一律保留** —— 发送失败、陈旧令牌、非 2xx 正是别人
grep 的对象,静音它们是坏交易。实测同样 12 秒:36 行 → 4 行。
## 3. Link.ID 在 ReplaceLinks 之后必然失效
ReplaceLinks 是 DELETE + 重新 INSERT,sqlite 给每行**新的自增 id**。
任何在改写前捕获的 Link(典型:随 token 环跑的 Link)手里的 id 要么查无
此行,要么命中另一条转发 —— 实测捕获 alpha id=1,改写后新表是 3/4/5,
GetLink(1) 直接落空。
新增 LinkByTriple(local, remote, port) 按自然键查(业务代码本来就一律用
这个三元组标识转发),并把 claim/reconcile 切过去。查无行返回
(Link{}, false, nil) 而非 error:新建的转发没有行,应当照常启动。
## 4. homeagent_device 孤儿(已澄清,非独立缺陷)
它 disabled=1 且从不在 topology 里,是缺陷 1 的另一面(停用标记没进
token),随本次修复覆盖,无需单独处理。
## 测试
新增 4 个测试文件,重点是**验证测试本身抓得住 bug**:
- 临时回退 `ln.Disabled = true` 这行 → TestStopForwardPublishesDisabled-
FlagInRevokeTask 如期变红,还原后变绿
- ⚠️ 第一版回归测试只断言 store 层,是**假绿**:newTestHandler 的 Ring
为 nil,RevokeTask 那条(真正坏掉的)路根本没执行。补了带 ring 的
newRingTestHandler,直接断言**发布出去的 task 上的 flag**
- LinkByTriple 在 ReplaceLinks 前后保持稳定;GetLink(id) 的失效被固化成
一个可见的说明性测试
- 停用/start 往返、per-forward 停用不误伤兄弟转发
- 错误路径不静音、W4F_DEBUG 各种取值
go build / go vet / go test ./... 全绿,gofmt 干净。
This commit is contained in:
91
internal/cluster/debug.go
Normal file
91
internal/cluster/debug.go
Normal file
@ -0,0 +1,91 @@
|
||||
package cluster
|
||||
|
||||
import (
|
||||
"log"
|
||||
"os"
|
||||
"sync/atomic"
|
||||
)
|
||||
|
||||
// logf is the package's logging seam: every cluster log line funnels through it
|
||||
// so the debug gate in debug.go has a single place to hook.
|
||||
func logf(format string, args ...any) { log.Printf(format, args...) }
|
||||
|
||||
// Token rotation is the ring's heartbeat: with a 2s round delay it fires
|
||||
// continuously, and the default three log lines per round
|
||||
// ("OnToken cycle=N" / "forward cycle=N to X" / "token-send ... -> 200")
|
||||
// carry no information — no cycle number, address, timing or payload ever
|
||||
// changes in the steady state. Measured on the live 3-node cluster that was
|
||||
// ~510k lines/day on one node (3.5M lines in a week), which drowns every real
|
||||
// event in the journal and fills the disk for a signal that is already
|
||||
// available in structured form via GET /api/manager/cluster/ring (cycle,
|
||||
// lastSync, roundDelayMs, node aliveness).
|
||||
//
|
||||
// So the steady-state lines are demoted to a debug level, off by default and
|
||||
// enabled with W4F_DEBUG=token (or 1/all/true for every debug line). Failure
|
||||
// paths are NOT demoted: a send error, a stale token, a timeout or a leader
|
||||
// change is exactly what someone is grepping for, and losing those to a quiet
|
||||
// default would be a bad trade.
|
||||
const debugEnv = "W4F_DEBUG"
|
||||
|
||||
// debugToken logs a per-token-round heartbeat line. Suppressed unless
|
||||
// W4F_DEBUG selects "token" (or a catch-all value).
|
||||
func debugToken(format string, args ...any) {
|
||||
if debugTokenOn.Load() {
|
||||
logf(format, args...)
|
||||
}
|
||||
}
|
||||
|
||||
// debugAll logs an ad-hoc diagnostic line. Suppressed unless W4F_DEBUG is set
|
||||
// to a catch-all value (1/all/true/*).
|
||||
func debugAll(format string, args ...any) {
|
||||
if debugAllOn.Load() {
|
||||
logf(format, args...)
|
||||
}
|
||||
}
|
||||
|
||||
var (
|
||||
debugTokenOn atomic.Bool
|
||||
debugAllOn atomic.Bool
|
||||
)
|
||||
|
||||
func init() { ReloadDebug() }
|
||||
|
||||
// ReloadDebug re-reads W4F_DEBUG. Called once at init so tests can flip it
|
||||
// without restarting, and available at runtime for an operator who wants to
|
||||
// watch the ring without a redeploy.
|
||||
func ReloadDebug() {
|
||||
v := os.Getenv(debugEnv)
|
||||
switch normalized := normalizeDebugValue(v); normalized {
|
||||
case "token":
|
||||
debugTokenOn.Store(true)
|
||||
debugAllOn.Store(false)
|
||||
case "all":
|
||||
debugTokenOn.Store(true)
|
||||
debugAllOn.Store(true)
|
||||
default:
|
||||
debugTokenOn.Store(false)
|
||||
debugAllOn.Store(false)
|
||||
}
|
||||
}
|
||||
|
||||
func normalizeDebugValue(v string) string {
|
||||
// Compare case-insensitively without pulling in strings just for this.
|
||||
out := make([]rune, 0, len(v))
|
||||
for _, r := range v {
|
||||
if r >= 'A' && r <= 'Z' {
|
||||
r += 'a' - 'A'
|
||||
}
|
||||
out = append(out, r)
|
||||
}
|
||||
s := string(out)
|
||||
switch s {
|
||||
case "":
|
||||
return ""
|
||||
case "token", "tokens", "ring":
|
||||
return "token"
|
||||
}
|
||||
// Any other non-empty value is a deliberate request for more output, so it
|
||||
// is treated as a catch-all rather than silently muting the operator who
|
||||
// set it. "0" lands here too: it was asked for, so honour it.
|
||||
return "all"
|
||||
}
|
||||
108
internal/cluster/debug_test.go
Normal file
108
internal/cluster/debug_test.go
Normal file
@ -0,0 +1,108 @@
|
||||
package cluster
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"log"
|
||||
"os"
|
||||
"strings"
|
||||
"testing"
|
||||
)
|
||||
|
||||
// captureLog redirects the standard logger into a buffer for the duration of
|
||||
// fn and returns what was written.
|
||||
func captureLog(t *testing.T, fn func()) string {
|
||||
t.Helper()
|
||||
var buf bytes.Buffer
|
||||
orig := log.Writer()
|
||||
origFlags := log.Flags()
|
||||
log.SetOutput(&buf)
|
||||
log.SetFlags(0)
|
||||
defer func() {
|
||||
log.SetOutput(orig)
|
||||
log.SetFlags(origFlags)
|
||||
}()
|
||||
fn()
|
||||
return buf.String()
|
||||
}
|
||||
|
||||
func TestDebugTokenSuppressedByDefault(t *testing.T) {
|
||||
os.Unsetenv(debugEnv)
|
||||
ReloadDebug()
|
||||
|
||||
out := captureLog(t, func() {
|
||||
debugToken("ring[%s] OnToken cycle=%d", "node:7500", 42)
|
||||
debugToken("ring[%s] forward cycle=%d to %s", "node:7500", 42, "next:7500")
|
||||
debugToken("token-send %s: size=%dB elapsed=%v -> %d", "next:7500", 5605, "170ms", 200)
|
||||
})
|
||||
if out != "" {
|
||||
t.Fatalf("steady-state token lines logged with W4F_DEBUG unset: %q", out)
|
||||
}
|
||||
}
|
||||
|
||||
func TestDebugTokenEnabledByEnv(t *testing.T) {
|
||||
for _, v := range []string{"token", "TOKEN", "tokens", "ring", "1", "true", "yes", "all", "*", "yes-please"} {
|
||||
t.Run(v, func(t *testing.T) {
|
||||
t.Setenv(debugEnv, v)
|
||||
ReloadDebug()
|
||||
if !debugTokenOn.Load() {
|
||||
t.Fatalf("W4F_DEBUG=%q should enable the token heartbeat", v)
|
||||
}
|
||||
out := captureLog(t, func() {
|
||||
debugToken("ring[%s] OnToken cycle=%d", "node:7500", 7)
|
||||
})
|
||||
if !strings.Contains(out, "OnToken cycle=7") {
|
||||
t.Fatalf("W4F_DEBUG=%q: expected the line to be logged, got %q", v, out)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// The whole point of the gate is to shrink the journal, so the failure paths
|
||||
// must stay loud without any env var — losing a send error to a quiet default
|
||||
// would be a bad trade.
|
||||
func TestFailurePathsStayLoud(t *testing.T) {
|
||||
os.Unsetenv(debugEnv)
|
||||
ReloadDebug()
|
||||
|
||||
out := captureLog(t, func() {
|
||||
logf("token-send %s: size=%dB elapsed=%v err=%v", "down:7500", 10, "5ms", "connection refused")
|
||||
})
|
||||
if !strings.Contains(out, "connection refused") {
|
||||
t.Fatalf("send errors must never be gated: got %q", out)
|
||||
}
|
||||
}
|
||||
|
||||
func TestDebugAllOffForTokenOnly(t *testing.T) {
|
||||
t.Setenv(debugEnv, "token")
|
||||
ReloadDebug()
|
||||
if !debugTokenOn.Load() {
|
||||
t.Fatal("token level should enable debugToken")
|
||||
}
|
||||
if debugAllOn.Load() {
|
||||
t.Fatal("token level must not enable the catch-all debugAll")
|
||||
}
|
||||
out := captureLog(t, func() { debugAll("scratch diagnostic") })
|
||||
if out != "" {
|
||||
t.Fatalf("debugAll should stay off at token level, got %q", out)
|
||||
}
|
||||
}
|
||||
|
||||
func TestNormalizeDebugValue(t *testing.T) {
|
||||
cases := map[string]string{
|
||||
"": "",
|
||||
"token": "token",
|
||||
"TOKEN": "token",
|
||||
"Ring": "token",
|
||||
"1": "all",
|
||||
"true": "all",
|
||||
"ALL": "all",
|
||||
"*": "all",
|
||||
"anything": "all", // unrecognised but deliberate → don't silence it
|
||||
"0": "all", // 0 is still a deliberate request for output
|
||||
}
|
||||
for in, want := range cases {
|
||||
if got := normalizeDebugValue(in); got != want {
|
||||
t.Errorf("normalizeDebugValue(%q) = %q, want %q", in, got, want)
|
||||
}
|
||||
}
|
||||
}
|
||||
@ -182,7 +182,9 @@ func (e *Engine) OnToken(ctx context.Context, tk *Token) (*Token, error) {
|
||||
if tk.SentAt > e.lastTokenAt {
|
||||
e.lastTokenAt = tk.SentAt
|
||||
}
|
||||
log.Printf("ring[%s] OnToken cycle=%d", e.ID, tk.Cycle)
|
||||
// Per-round heartbeat — steady state, no information. See debug.go: this
|
||||
// fired ~2x/second and dominated the journal on every node.
|
||||
debugToken("ring[%s] OnToken cycle=%d", e.ID, tk.Cycle)
|
||||
|
||||
// Parallel rhythm timer: operations run while the pace clock ticks.
|
||||
// Delay scales with alive node count (more nodes → lower per-hop delay,
|
||||
@ -792,6 +794,14 @@ func (e *Engine) RemoveNode(nodeID string) *Task {
|
||||
return e.state.AddRemoveNode(nodeID)
|
||||
}
|
||||
|
||||
// RemoveTopologyEntry drops the active topology entry for a forward identified
|
||||
// by its natural key. Exposed so the app's claim path can retire an entry it
|
||||
// refuses to serve (see ClaimFn: a disabled forward must stop looking active,
|
||||
// otherwise the startup reconcile keeps re-claiming it on every restart).
|
||||
func (e *Engine) RemoveTopologyEntry(local, remote string, port int) bool {
|
||||
return e.state.RemoveTopology(local, remote, port)
|
||||
}
|
||||
|
||||
// RevokeTask publishes a revocation for an established forward through the
|
||||
// same token channel; the owning node stops the worker and drops topology.
|
||||
func (e *Engine) RevokeTask(local store.Local, remote store.Remote, link store.Link) *Task {
|
||||
|
||||
@ -128,7 +128,7 @@ func (e *Engine) forwardToNext(ctx context.Context, tk *Token) error {
|
||||
if e.send == nil {
|
||||
return nil
|
||||
}
|
||||
log.Printf("ring[%s] forward cycle=%d to %s", e.ID, tk.Cycle, next)
|
||||
debugToken("ring[%s] forward cycle=%d to %s", e.ID, tk.Cycle, next)
|
||||
err := e.send(ctx, next, tk)
|
||||
if err == nil {
|
||||
if e.state.LeaderID == e.ID {
|
||||
|
||||
@ -8,7 +8,6 @@ import (
|
||||
"context"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"log"
|
||||
"net/http"
|
||||
"time"
|
||||
)
|
||||
@ -52,11 +51,16 @@ func (t *TokenTransport) SendTo(getAddr func(nodeID string) string) func(ctx con
|
||||
start := time.Now()
|
||||
resp, err := cli.Do(req)
|
||||
if err != nil {
|
||||
log.Printf("token-send %s: size=%dB elapsed=%v err=%v", addr, len(body), time.Since(start).Round(time.Millisecond), err)
|
||||
// NOT demoted: a failed send is the "neighbor offline" signal the
|
||||
// ring's fault paths are diagnosed from.
|
||||
logf("token-send %s: size=%dB elapsed=%v err=%v", addr, len(body), time.Since(start).Round(time.Millisecond), err)
|
||||
return err
|
||||
}
|
||||
defer resp.Body.Close()
|
||||
log.Printf("token-send %s: size=%dB elapsed=%v -> %d", addr, len(body), time.Since(start).Round(time.Millisecond), resp.StatusCode)
|
||||
// Success path is a per-round heartbeat (size/elapsed/200 repeat
|
||||
// verbatim every cycle) — debug only. The status-code check below stays
|
||||
// loud on purpose, so a non-2xx still shows up without the debug flag.
|
||||
debugToken("token-send %s: size=%dB elapsed=%v -> %d", addr, len(body), time.Since(start).Round(time.Millisecond), resp.StatusCode)
|
||||
if resp.StatusCode >= 400 {
|
||||
return fmt.Errorf("token POST %s -> HTTP %d", url, resp.StatusCode)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user