From b65c2c00b3e636ba408dc2c7a3e63227d022fc32 Mon Sep 17 00:00:00 2001 From: Lemon-miaow Date: Sat, 26 Sep 2026 00:33:04 +0800 Subject: [PATCH] =?UTF-8?q?feat(plugins):=20=E6=8F=92=E4=BB=B6=E4=BE=A7?= =?UTF-8?q?=E8=AE=A1=E6=95=B0=E5=99=A8=E4=B8=8E=E5=91=A8=E6=9C=9F=E5=81=A5?= =?UTF-8?q?=E5=BA=B7=E6=97=A5=E5=BF=97=EF=BC=8CLimbo/=E5=88=B7=E6=96=B0?= =?UTF-8?q?=E5=A4=B1=E8=B4=A5=E6=8C=89=E6=95=85=E9=9A=9C=E5=91=A8=E6=9C=9F?= =?UTF-8?q?=E5=8D=87=E7=BA=A7=E6=97=A5=E5=BF=97?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/troubleshooting.md | 30 +++++ plugins/README.md | 10 ++ .../lolicon/felis/limbo/FelisLimboPlugin.java | 35 +++++- .../best/lolicon/felis/link/ApiStats.java | 103 ++++++++++++++++++ .../lolicon/felis/link/FelisApiClient.java | 18 ++- .../lolicon/felis/link/OutageTracker.java | 75 +++++++++++++ .../felis/link/FelisApiClientRetryTest.java | 60 +++++++++- .../lolicon/felis/link/OutageTrackerTest.java | 62 +++++++++++ plugins/test.sh | 19 +++- .../felis/velocity/FelisVelocityPlugin.java | 68 ++++++++++-- .../lolicon/felis/velocity/ProxyStats.java | 71 ++++++++++++ .../lolicon/felis/velocity/WaitingRouter.java | 8 ++ .../felis/velocity/ProxyStatsTest.java | 92 ++++++++++++++++ 13 files changed, 634 insertions(+), 17 deletions(-) create mode 100644 plugins/shared/src/main/java/best/lolicon/felis/link/ApiStats.java create mode 100644 plugins/shared/src/main/java/best/lolicon/felis/link/OutageTracker.java create mode 100644 plugins/shared/test/best/lolicon/felis/link/OutageTrackerTest.java create mode 100644 plugins/velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java create mode 100644 plugins/velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 6a587ec..d953371 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -1439,6 +1439,36 @@ kubectl -n felis logs deploy/felis-api | grep 'msg=request' | grep 'status=5' kubectl -n felis logs deploy/felis-api | grep 'request_id=' ``` +The plugins' calls are the `face="internal"` series, one route per call: a +failing join-event, wake or link-status poll shows up as its own route. + +```promql +sum by (route, code) (rate(felis_http_requests_total{face="internal", route="/api/v1/internal/servers/{name}/join-event"}[5m])) +sum by (route, code) (rate(felis_http_requests_total{face="internal", route="/api/v1/internal/servers/{name}/wake"}[5m])) +histogram_quantile(0.95, sum by (le, route) (rate(felis_http_request_duration_seconds_bucket{face="internal"}[5m]))) +``` + +A call that never reached felis-api (refused, reset, timed out) is missing from +those series; the caller counts it. The proxy logs one line per active 10 minutes +with felis-api as it saw it plus its own failures, and `/felis` at the proxy +console prints the totals since start: + +```bash +journalctl -u felis-velocity | grep 'Felis: last 10 min' +# Felis: last 10 min: felis-api calls=412 (no answer=0, 4xx=3, 5xx=0, retried=0), avg=18 ms, max=240 ms, +# busy refusals=0, join-events failed=0, join-events dropped=0, transfers failed=0, +# server-list refreshes failed=0, waiting now=0 +journalctl -u felis-velocity | grep 'server list refresh' +kubectl -n minecraft logs login-0 | grep 'link status poll' +``` + +`no answer` rising with a flat `felis_http_requests_total` means the path to the +internal face is broken (NetworkPolicy, Service, the api Pod down); `busy +refusals` or `join-events dropped` above zero means felis-api is slower than the +proxy's pool of 8 threads can absorb. A refresh or link-status outage warns when it +starts, every 5 minutes while it lasts with the failure count, and at info when +it recovers. + ### Scraping The series come from two processes. Both Services carry the diff --git a/plugins/README.md b/plugins/README.md index 828d3ea..21c48c4 100644 --- a/plugins/README.md +++ b/plugins/README.md @@ -192,6 +192,16 @@ one is still going. Acting commands (`/link`, `/felis claim`, migrate, op approve) share a per-player budget of 5 then one per 5 s; felis:control frames from the lobby are metered per player and menu status answers are cached. +Health on the proxy: every 10 minutes that saw any activity the proxy logs one +info line, `Felis: last 10 min: felis-api calls=… (no answer=…, 4xx=…, 5xx=…, +retried=…), avg=… ms, max=… ms, busy refusals=…, join-events failed=…, +join-events dropped=…, transfers failed=…, server-list refreshes failed=…, +waiting now=…`, with only that window's counts. `/felis` run from the console +adds the same felis-api counts since start, the waiting count and the failure +totals. A server-list refresh that keeps failing warns once when it starts, then +every 5 minutes with the running count, and logs at info when it recovers; the +login gate treats its link-status polls the same way. + ## Lobby menu (§12) The `paper/` module is the lobby's player-facing face for §27 scenario 10 diff --git a/plugins/limbo/src/main/java/best/lolicon/felis/limbo/FelisLimboPlugin.java b/plugins/limbo/src/main/java/best/lolicon/felis/limbo/FelisLimboPlugin.java index 7c531f4..fdecf92 100644 --- a/plugins/limbo/src/main/java/best/lolicon/felis/limbo/FelisLimboPlugin.java +++ b/plugins/limbo/src/main/java/best/lolicon/felis/limbo/FelisLimboPlugin.java @@ -8,6 +8,7 @@ import best.lolicon.felis.link.LinkCode; import best.lolicon.felis.link.LinkConfig; import best.lolicon.felis.link.LinkConfigLoader; import best.lolicon.felis.link.LinkException; +import best.lolicon.felis.link.OutageTracker; import com.loohp.limbo.events.EventHandler; import com.loohp.limbo.events.Listener; @@ -121,6 +122,8 @@ public final class FelisLimboPlugin extends LimboPlugin implements Listener { static final long START_RETRY_WINDOW_MILLIS = 60_000L; // How long the release is re-sent after sign-in before giving up with a message. private static final long RELEASE_WINDOW_MILLIS = 120_000L; + // How often a link-status outage is summarized while it lasts. + private static final long POLL_OUTAGE_REPEAT_MILLIS = 5 * 60_000L; // ---- readiness state ---- private final AtomicBoolean ready = new AtomicBoolean(false); @@ -141,6 +144,11 @@ public final class FelisLimboPlugin extends LimboPlugin implements Listener { // Players whose release loop is running; the async link poll can observe "linked" // twice before its cancellation lands, and the release must start once. private final Set releasing = ConcurrentHashMap.newKeySet(); + // One tracker for every player's link poll: the polls share felis-api, so an outage + // is one event, reported when it starts, every few minutes while it lasts, and when + // it ends, rather than once a second per waiting player (or never, at FINE). + private final OutageTracker pollOutage = + new OutageTracker(POLL_OUTAGE_REPEAT_MILLIS, System::currentTimeMillis); @Override public void onEnable() { @@ -324,7 +332,8 @@ public final class FelisLimboPlugin extends LimboPlugin implements Listener { } catch (RuntimeException e) { // A client that refuses the book (rare) still gets the chat instructions // below, so a book failure is not fatal to the flow. - LOG.fine("FelisLimbo: openBook failed for " + id + " — " + e.getMessage()); + LOG.warning("FelisLimbo: openBook failed for " + id + " — " + e.getMessage() + + "; the code is still sent in chat"); } player.sendMessage("§e[Felis] 绑定码 / Code: §6" + code.code()); player.sendMessage("§e[Felis] 用系统浏览器打开 §b" + url @@ -348,13 +357,29 @@ public final class FelisLimboPlugin extends LimboPlugin implements Listener { disconnectOnMain(id, "登录超时，请重连 / Login timed out. Please reconnect."); return; } + boolean linked; try { - if (apiClient.linkStatus(id)) { - getServer().getScheduler().runTask(this, () -> startRelease(id)); - } + linked = apiClient.linkStatus(id); } catch (LinkException e) { // A transient poll failure is not fatal — keep trying until the deadline. - LOG.fine("FelisLimbo: link status poll failed for " + id + " — " + e.getMessage()); + OutageTracker.Report report = pollOutage.failure(); + if (report == OutageTracker.Report.DOWN) { + LOG.warning("FelisLimbo: link status poll failed for " + id + " — " + e.getMessage() + + "; players keep waiting, and repeats are summarized every " + + POLL_OUTAGE_REPEAT_MILLIS / 60_000L + " min until it recovers"); + } else if (report == OutageTracker.Report.STILL_DOWN) { + LOG.warning("FelisLimbo: link status polls still failing: " + pollOutage.failures() + + " failed polls over " + pollOutage.downForMillis() / 1000 + " s, last — " + + e.getMessage()); + } + return; + } + if (pollOutage.success() == OutageTracker.Report.RECOVERED) { + LOG.info("FelisLimbo: link status polls recovered after " + pollOutage.lastOutageFailures() + + " failed polls over " + pollOutage.lastOutageMillis() / 1000 + " s"); + } + if (linked) { + getServer().getScheduler().runTask(this, () -> startRelease(id)); } } diff --git a/plugins/shared/src/main/java/best/lolicon/felis/link/ApiStats.java b/plugins/shared/src/main/java/best/lolicon/felis/link/ApiStats.java new file mode 100644 index 0000000..b58c5e4 --- /dev/null +++ b/plugins/shared/src/main/java/best/lolicon/felis/link/ApiStats.java @@ -0,0 +1,103 @@ +package best.lolicon.felis.link; + +import java.util.concurrent.atomic.AtomicLong; + +/** + * ApiStats counts what a {@link FelisApiClient} sent and how it came back, so the + * plugin can report felis-api's health as its callers see it: calls, the ones that + * never got an answer (refused, reset, timed out), 4xx and 5xx answers, retries, and + * latency. Every attempt is one call, a retried GET counting twice. Counters only + * grow; {@link #window()} hands out what changed since the previous window, which is + * what a periodic log line wants. + */ +public final class ApiStats { + private final AtomicLong calls = new AtomicLong(); + private final AtomicLong transport = new AtomicLong(); + private final AtomicLong clientErrors = new AtomicLong(); + private final AtomicLong serverErrors = new AtomicLong(); + private final AtomicLong retries = new AtomicLong(); + private final AtomicLong totalMillis = new AtomicLong(); + private final AtomicLong windowMaxMillis = new AtomicLong(); + private final AtomicLong maxMillis = new AtomicLong(); + private Snapshot lastWindow = new Snapshot(0, 0, 0, 0, 0, 0, 0); + + /** record notes one attempt: its HTTP status (0 when no answer came) and how long it took. */ + void record(int status, long millis) { + calls.incrementAndGet(); + if (status == 0) { + transport.incrementAndGet(); + } else if (status >= 500) { + serverErrors.incrementAndGet(); + } else if (status >= 400) { + clientErrors.incrementAndGet(); + } + totalMillis.addAndGet(millis); + windowMaxMillis.accumulateAndGet(millis, Math::max); + maxMillis.accumulateAndGet(millis, Math::max); + } + + void retried() { + retries.incrementAndGet(); + } + + /** total is every count since the client was made, with the slowest call ever. */ + public Snapshot total() { + return new Snapshot(calls.get(), transport.get(), clientErrors.get(), serverErrors.get(), + retries.get(), totalMillis.get(), maxMillis.get()); + } + + /** + * window returns the counts since the previous call (the first call: since the + * client was made), with the slowest call in that span, and starts a new window, so + * consecutive windows never overlap. + */ + public synchronized Snapshot window() { + long max = windowMaxMillis.getAndSet(0); + Snapshot now = new Snapshot(calls.get(), transport.get(), clientErrors.get(), serverErrors.get(), + retries.get(), totalMillis.get(), max); + Snapshot delta = new Snapshot( + now.calls - lastWindow.calls, + now.transport - lastWindow.transport, + now.clientErrors - lastWindow.clientErrors, + now.serverErrors - lastWindow.serverErrors, + now.retries - lastWindow.retries, + now.totalMillis - lastWindow.totalMillis, + max); + lastWindow = now; + return delta; + } + + /** Snapshot is one immutable reading of the counters. */ + public static final class Snapshot { + public final long calls; + public final long transport; + public final long clientErrors; + public final long serverErrors; + public final long retries; + public final long totalMillis; + public final long maxMillis; + + Snapshot(long calls, long transport, long clientErrors, long serverErrors, + long retries, long totalMillis, long maxMillis) { + this.calls = calls; + this.transport = transport; + this.clientErrors = clientErrors; + this.serverErrors = serverErrors; + this.retries = retries; + this.totalMillis = totalMillis; + this.maxMillis = maxMillis; + } + + /** avgMillis is the mean call time, 0 with no calls. */ + public long avgMillis() { + return calls == 0 ? 0 : totalMillis / calls; + } + + /** summary is the one-line form the plugins log and print. */ + public String summary() { + return "calls=" + calls + " (no answer=" + transport + ", 4xx=" + clientErrors + + ", 5xx=" + serverErrors + ", retried=" + retries + "), avg=" + avgMillis() + + " ms, max=" + maxMillis + " ms"; + } + } +} diff --git a/plugins/shared/src/main/java/best/lolicon/felis/link/FelisApiClient.java b/plugins/shared/src/main/java/best/lolicon/felis/link/FelisApiClient.java index 5cbfd23..8dcc7e2 100644 --- a/plugins/shared/src/main/java/best/lolicon/felis/link/FelisApiClient.java +++ b/plugins/shared/src/main/java/best/lolicon/felis/link/FelisApiClient.java @@ -54,6 +54,7 @@ public final class FelisApiClient { private final LinkConfig config; private final HttpClient http; + private final ApiStats stats = new ApiStats(); public FelisApiClient(LinkConfig config) { this.config = Objects.requireNonNull(config, "config"); @@ -62,6 +63,11 @@ public final class FelisApiClient { .build(); } + /** stats counts this client's calls and their outcomes, for the plugin's health line. */ + public ApiStats stats() { + return stats; + } + /** listServers returns the lifecycle view of every MinecraftServer (GET /servers). */ public List listServers() throws LinkException { return ServerView.listFrom(getObject("/api/v1/servers", 200)); @@ -297,6 +303,7 @@ public final class FelisApiClient { } catch (InterruptedException e) { throw interrupted(e); } + stats.retried(); return expectObject(send(req), expect); } @@ -338,8 +345,17 @@ public final class FelisApiClient { } } + // exchange is the one place a request goes out, so every attempt is counted once. private HttpResponse exchange(HttpRequest req) throws IOException, InterruptedException { - return http.send(req, HttpResponse.BodyHandlers.ofString()); + long start = System.nanoTime(); + int status = 0; + try { + HttpResponse res = http.send(req, HttpResponse.BodyHandlers.ofString()); + status = res.statusCode(); + return res; + } finally { + stats.record(status, (System.nanoTime() - start) / 1_000_000); + } } // A refused connection arrives as a ConnectException with no message; the class diff --git a/plugins/shared/src/main/java/best/lolicon/felis/link/OutageTracker.java b/plugins/shared/src/main/java/best/lolicon/felis/link/OutageTracker.java new file mode 100644 index 0000000..1460f4c --- /dev/null +++ b/plugins/shared/src/main/java/best/lolicon/felis/link/OutageTracker.java @@ -0,0 +1,75 @@ +package best.lolicon.felis.link; + +import java.util.function.LongSupplier; + +/** + * OutageTracker decides which failures of a repeated felis-api call are worth a log + * line. A poll that runs every few seconds for every waiting player would bury the + * log if each failure were a warning, and hides the outage entirely if each is a + * debug line. Instead: the first failure after a success is {@link Report#DOWN} + * (log a warning), later failures are {@link Report#STILL_DOWN} at most once per + * {@code repeatMillis} (a reminder with the running count), the first success after + * failures is {@link Report#RECOVERED} (log how long it lasted), and everything + * else is {@link Report#NONE}. + */ +public final class OutageTracker { + public enum Report { NONE, DOWN, STILL_DOWN, RECOVERED } + + private final LongSupplier clock; + private final long repeatMillis; + private long downSince = -1; + private long lastReport; + private long failures; + private long lastOutageFailures; + private long lastOutageMillis; + + public OutageTracker(long repeatMillis, LongSupplier clock) { + this.repeatMillis = repeatMillis; + this.clock = clock; + } + + public synchronized Report failure() { + long now = clock.getAsLong(); + failures++; + if (downSince < 0) { + downSince = now; + lastReport = now; + return Report.DOWN; + } + if (now - lastReport >= repeatMillis) { + lastReport = now; + return Report.STILL_DOWN; + } + return Report.NONE; + } + + public synchronized Report success() { + if (downSince < 0) { + return Report.NONE; + } + lastOutageFailures = failures; + lastOutageMillis = clock.getAsLong() - downSince; + downSince = -1; + failures = 0; + return Report.RECOVERED; + } + + /** failures is how many calls have failed in the current outage (0 when up). */ + public synchronized long failures() { + return failures; + } + + /** downForMillis is how long the current outage has lasted (0 when up). */ + public synchronized long downForMillis() { + return downSince < 0 ? 0 : clock.getAsLong() - downSince; + } + + /** lastOutageFailures and lastOutageMillis describe the outage a RECOVERED report just closed. */ + public synchronized long lastOutageFailures() { + return lastOutageFailures; + } + + public synchronized long lastOutageMillis() { + return lastOutageMillis; + } +} diff --git a/plugins/shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java b/plugins/shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java index 7fd89a4..2d1ad63 100644 --- a/plugins/shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java +++ b/plugins/shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java @@ -20,7 +20,8 @@ import java.util.concurrent.atomic.AtomicInteger; * felis-api that counts the requests each path receives: a GET is tried once more * after a connection that dropped mid-reply or a 502/503/504, never a third time; a POST is * never repeated (the first attempt may have landed); a GET that ran past the - * request timeout is cut off at that timeout and not repeated. + * request timeout is cut off at that timeout and not repeated. It then checks the + * client's {@link ApiStats} against the requests the stub saw. * *

Run: {@code javac -d shared/src/main/java/best/lolicon/felis/link/*.java * shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java && java -cp @@ -49,6 +50,8 @@ public final class FelisApiClientRetryTest { getIsNotRetriedOnAClientError(api); postIsNeverRetried(api); timedOutGetIsCutOffAndNotRetried(api); + statsCountEveryAttempt(api); + statsArithmetic(); } finally { stub.stop(0); pool.shutdownNow(); @@ -149,6 +152,61 @@ public final class FelisApiClientRetryTest { assertEq("slow requests", 1, count("GET /api/v1/internal/servers/slow/status")); } + // The calls above, attempt by attempt: flaky 503+200, cut dropped+200, down 502+502, + // gone 404, busy 503 (POST), slow timed out. Nine attempts, three of them retries; + // no answer twice (the cut reply, the timeout), one 4xx, four 5xx. + private static void statsCountEveryAttempt(FelisApiClient api) throws LinkException { + ApiStats.Snapshot t = api.stats().total(); + int sent = hits.values().stream().mapToInt(AtomicInteger::get).sum(); + assertEq("stats calls = requests the stub saw", (long) sent, t.calls); + assertEq("stats calls", 9L, t.calls); + assertEq("stats no answer", 2L, t.transport); + assertEq("stats 4xx", 1L, t.clientErrors); + assertEq("stats 5xx", 4L, t.serverErrors); + assertEq("stats retried", 3L, t.retries); + // The slowest attempt is the one cut off by the 400 ms request timeout. + if (t.maxMillis < 390 || t.maxMillis >= 1200) { + throw new AssertionError("stats max: " + t.maxMillis + " ms, want the ~400 ms timeout"); + } + checks++; + + ApiStats.Snapshot w1 = api.stats().window(); + assertEq("first window = totals so far", 9L, w1.calls); + assertEq("first window 5xx", 4L, w1.serverErrors); + assertEq("first window max", t.maxMillis, w1.maxMillis); + ApiStats.Snapshot w2 = api.stats().window(); + assertEq("empty window calls", 0L, w2.calls); + assertEq("empty window max", 0L, w2.maxMillis); + assertEq("empty window avg", 0L, w2.avgMillis()); + assertEq("total max outlives the windows", t.maxMillis, api.stats().total().maxMillis); + api.serverStatus("flaky"); // answers 200 from now on + ApiStats.Snapshot w3 = api.stats().window(); + assertEq("next window calls", 1L, w3.calls); + assertEq("next window 5xx", 0L, w3.serverErrors); + assertEq("next window retried", 0L, w3.retries); + assertEq("totals keep growing", 10L, api.stats().total().calls); + } + + // The status classes at their edges and the latency figures, on fixed inputs. + private static void statsArithmetic() { + ApiStats s = new ApiStats(); + s.record(200, 10); + s.record(399, 40); + s.record(400, 30); + s.record(499, 5); + s.record(500, 20); + s.record(0, 15); + ApiStats.Snapshot t = s.total(); + assertEq("edge calls", 6L, t.calls); + assertEq("edge 4xx (400, 499)", 2L, t.clientErrors); + assertEq("edge 5xx (500)", 1L, t.serverErrors); + assertEq("edge no answer", 1L, t.transport); + assertEq("avg of 10+40+30+5+20+15 over 6", 20L, t.avgMillis()); + assertEq("max is the slowest, not the last", 40L, t.maxMillis); + assertEq("summary", "calls=6 (no answer=1, 4xx=2, 5xx=1, retried=0), avg=20 ms, max=40 ms", + t.summary()); + } + // ---- harness ---- interface Call { diff --git a/plugins/shared/test/best/lolicon/felis/link/OutageTrackerTest.java b/plugins/shared/test/best/lolicon/felis/link/OutageTrackerTest.java new file mode 100644 index 0000000..f8cf8a2 --- /dev/null +++ b/plugins/shared/test/best/lolicon/felis/link/OutageTrackerTest.java @@ -0,0 +1,62 @@ +package best.lolicon.felis.link; + +import java.util.concurrent.atomic.AtomicLong; + +/** + * OutageTrackerTest walks an {@link OutageTracker} through an outage on an injected + * clock: one DOWN on the first failure, STILL_DOWN no more than once per repeat + * interval, RECOVERED once with the outage's length and failure count, and silence + * while all is well. + * + *

Run: {@code javac -d shared/src/main/java/best/lolicon/felis/link/*.java + * shared/test/best/lolicon/felis/link/OutageTrackerTest.java && java -cp + * best.lolicon.felis.link.OutageTrackerTest}. + */ +public final class OutageTrackerTest { + + private static int checks; + + public static void main(String[] args) { + AtomicLong now = new AtomicLong(10_000L); + OutageTracker t = new OutageTracker(60_000L, now::get); + + assertEq("success while up", OutageTracker.Report.NONE, t.success()); + assertEq("failures while up", 0L, t.failures()); + + assertEq("first failure", OutageTracker.Report.DOWN, t.failure()); + now.addAndGet(2_000L); + assertEq("second failure 2 s later", OutageTracker.Report.NONE, t.failure()); + now.addAndGet(57_999L); // 59.999 s after DOWN + assertEq("just under the repeat interval", OutageTracker.Report.NONE, t.failure()); + now.addAndGet(1L); // 60 s after DOWN + assertEq("repeat interval reached", OutageTracker.Report.STILL_DOWN, t.failure()); + now.addAndGet(30_000L); + assertEq("half an interval after the reminder", OutageTracker.Report.NONE, t.failure()); + now.addAndGet(30_000L); + assertEq("an interval after the reminder", OutageTracker.Report.STILL_DOWN, t.failure()); + assertEq("failures in the outage", 6L, t.failures()); + assertEq("outage length so far", 120_000L, t.downForMillis()); + + now.addAndGet(5_000L); + assertEq("first success", OutageTracker.Report.RECOVERED, t.success()); + assertEq("closed outage failures", 6L, t.lastOutageFailures()); + assertEq("closed outage length", 125_000L, t.lastOutageMillis()); + assertEq("failures reset", 0L, t.failures()); + assertEq("down-for reset", 0L, t.downForMillis()); + assertEq("second success", OutageTracker.Report.NONE, t.success()); + + // A new outage starts its own count and is announced again at once. + now.addAndGet(1_000L); + assertEq("next outage", OutageTracker.Report.DOWN, t.failure()); + assertEq("next outage failures", 1L, t.failures()); + + System.out.println("OutageTrackerTest OK (" + checks + " checks)"); + } + + private static void assertEq(String what, Object want, Object got) { + if (!want.equals(got)) { + throw new AssertionError(what + ": got " + got + ", want " + want); + } + checks++; + } +} diff --git a/plugins/test.sh b/plugins/test.sh index 1d338f0..f6d0d41 100644 --- a/plugins/test.sh +++ b/plugins/test.sh @@ -14,7 +14,10 @@ # after a dropped reply or a 502/503/504 and a POST never, the request timeout # cuts a slow call off, felis-link.properties timeouts are validated, the # felis-api call pool refuses instead of growing and a repeating task never -# overlaps itself, the link-status outage +# overlaps itself, every felis-api attempt is counted by outcome and the +# periodic health line reports only a window's own counts (and stays quiet +# when idle), an outage is logged when it starts, every few minutes while it +# lasts and when it ends, the link-status outage # fallback fails closed outside its window, a proxy restarted during an API # outage routes on the last saved server list (and only until a fetch # succeeds), /invite prompts cannot double-fire @@ -87,6 +90,12 @@ javac -d "$work/shared-classes" \ plugins/shared/test/best/lolicon/felis/link/LinkConfigLoaderTest.java java -cp "$work/shared-classes" best.lolicon.felis.link.LinkConfigLoaderTest +echo "==> OutageTrackerTest (outage start / reminder / recovery log decisions, shared)" +javac -d "$work/shared-classes" \ + plugins/shared/src/main/java/best/lolicon/felis/link/*.java \ + plugins/shared/test/best/lolicon/felis/link/OutageTrackerTest.java +java -cp "$work/shared-classes" best.lolicon.felis.link.OutageTrackerTest + echo "==> ControlPolicyTest (who may send what on felis:control, velocity)" mkdir -p "$work/policy-classes" javac -d "$work/policy-classes" \ @@ -117,6 +126,14 @@ javac -d "$work/pool-classes" \ plugins/velocity/test/best/lolicon/felis/velocity/ApiPoolTest.java java -cp "$work/pool-classes" best.lolicon.felis.velocity.ApiPoolTest +echo "==> ProxyStatsTest (proxy failure counters and the periodic health line, velocity)" +mkdir -p "$work/stats-classes" +javac -d "$work/stats-classes" \ + plugins/shared/src/main/java/best/lolicon/felis/link/*.java \ + plugins/velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java \ + plugins/velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java +java -cp "$work/stats-classes" best.lolicon.felis.velocity.ProxyStatsTest + echo "==> InviteBookTest (/invite prompt store, velocity)" mkdir -p "$work/velocity-classes" javac -d "$work/velocity-classes" \ diff --git a/plugins/velocity/src/main/java/best/lolicon/felis/velocity/FelisVelocityPlugin.java b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/FelisVelocityPlugin.java index 5bb7671..125ce5a 100644 --- a/plugins/velocity/src/main/java/best/lolicon/felis/velocity/FelisVelocityPlugin.java +++ b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/FelisVelocityPlugin.java @@ -5,6 +5,7 @@ import best.lolicon.felis.link.LinkClient; import best.lolicon.felis.link.LinkCode; import best.lolicon.felis.link.LinkException; import best.lolicon.felis.link.OpLoginView; +import best.lolicon.felis.link.OutageTracker; import best.lolicon.felis.link.ServerView; import com.google.inject.Inject; @@ -87,6 +88,10 @@ public final class FelisVelocityPlugin { private static final int API_THREADS = 8; private static final int API_QUEUE = 64; private static final long BUSY_LOG_INTERVAL_MILLIS = 60_000L; + // One health line per window (ProxyStats.line), and a reminder at most this often + // while the server-list refresh keeps failing. + private static final Duration STATS_INTERVAL = Duration.ofMinutes(10); + private static final long REFRESH_OUTAGE_REPEAT_MILLIS = 5 * 60_000L; private final ProxyServer proxy; private final Logger logger; @@ -99,6 +104,9 @@ public final class FelisVelocityPlugin { private final FrameBudget commandBudget = new FrameBudget(5, 0.2, System::currentTimeMillis); private final BoundedExecutor apiCalls; private final AtomicLong lastBusyLog = new AtomicLong(); + private final ProxyStats stats = new ProxyStats(); + private final OutageTracker refreshOutage = + new OutageTracker(REFRESH_OUTAGE_REPEAT_MILLIS, System::currentTimeMillis); private FelisVelocityConfig config; private LinkClient linkClient; @@ -169,6 +177,7 @@ public final class FelisVelocityPlugin { refreshRegistrations(); repeating(REGISTRATION_REFRESH, this::refreshRegistrations); repeating(WAIT_POLL, router::tick); + repeating(STATS_INTERVAL, this::logStats); this.routingActive = true; logger.info("Felis routing ready: rootDomain={}, login={}, lobby={}. /link, /felis and /invite registered.", @@ -205,6 +214,7 @@ public final class FelisVelocityPlugin { if (apiCalls.submit(task)) { return true; } + stats.count(ProxyStats.Event.POOL_REFUSED); long now = System.currentTimeMillis(); long last = lastBusyLog.get(); if (now - last >= BUSY_LOG_INTERVAL_MILLIS && lastBusyLog.compareAndSet(last, now)) { @@ -214,6 +224,20 @@ public final class FelisVelocityPlugin { return false; } + /** stats is the proxy's failure counters, for the health line and /felis. */ + ProxyStats stats() { + return stats; + } + + // logStats writes the periodic health line; an idle window writes nothing. + private void logStats() { + String line = ProxyStats.line(STATS_INTERVAL.toMinutes(), apiClient.stats().window(), stats.window(), + router.waitingCount()); + if (line != null) { + logger.info(line); + } + } + /** async for a task a player is waiting on: a refusal is told to them at once. */ void async(Player player, Runnable task) { if (!async(task)) { @@ -263,15 +287,30 @@ public final class FelisVelocityPlugin { if (r.servers != null) { registry.refresh(r.servers); } - if (r.restored) { - logger.warn("Felis: felis-api is unreachable at startup (status={}): {}; routing to the {} backends " - + "in the saved server list until it answers.", - r.failure.statusCode(), r.failure.getMessage(), r.servers.size()); - } else if (r.failure != null) { - // Keep existing registrations on a control-plane blip (spec §11): a - // transient failure must never deregister live backends. - logger.warn("Felis: server list refresh failed (status={}): {}; keeping current registrations.", - r.failure.statusCode(), r.failure.getMessage()); + if (r.failure == null) { + if (refreshOutage.success() == OutageTracker.Report.RECOVERED) { + logger.info("Felis: server list refresh recovered after {} failed attempts over {} s.", + refreshOutage.lastOutageFailures(), refreshOutage.lastOutageMillis() / 1000); + } + } else { + stats.count(ProxyStats.Event.REFRESH_FAILED); + OutageTracker.Report report = refreshOutage.failure(); + if (r.restored) { + logger.warn("Felis: felis-api is unreachable at startup (status={}): {}; routing to the {} backends " + + "in the saved server list until it answers.", + r.failure.statusCode(), r.failure.getMessage(), r.servers.size()); + } else if (report == OutageTracker.Report.DOWN) { + // Keep existing registrations on a control-plane blip (spec §11): a + // transient failure must never deregister live backends. + logger.warn("Felis: server list refresh failed (status={}): {}; keeping current registrations. " + + "Repeats are summarized every {} min until it recovers.", + r.failure.statusCode(), r.failure.getMessage(), REFRESH_OUTAGE_REPEAT_MILLIS / 60_000L); + } else if (report == OutageTracker.Report.STILL_DOWN) { + logger.warn("Felis: server list refresh still failing: {} failed attempts over {} s, last (status={}): {}; " + + "keeping current registrations.", + refreshOutage.failures(), refreshOutage.downForMillis() / 1000, + r.failure.statusCode(), r.failure.getMessage()); + } } if (r.fileError != null) { logger.warn("Felis: saved server list {}: {}", r.failure == null ? "not written" : "not usable", @@ -492,6 +531,17 @@ public final class FelisVelocityPlugin { source.sendMessage(field("login", config.loginServer())); source.sendMessage(field("lobby", config.lobbyServer())); source.sendMessage(field("servers", String.valueOf(registry.all().size()))); + if (!(source instanceof Player)) { + // Operator health, console only: felis-api as this proxy sees it, and the + // proxy-side failures since start. + source.sendMessage(field("felis-api", apiClient.stats().total().summary())); + source.sendMessage(field("waiting", String.valueOf(router.waitingCount()))); + StringBuilder failures = new StringBuilder(); + for (ProxyStats.Event e : ProxyStats.Event.values()) { + failures.append(failures.length() == 0 ? "" : ", ").append(e.label).append('=').append(stats.total(e)); + } + source.sendMessage(field("since start", failures.toString())); + } source.sendMessage(Component.text( zh ? " /felis help 查看命令" : " /felis help for commands", NamedTextColor.GRAY)); } diff --git a/plugins/velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java new file mode 100644 index 0000000..cc0e371 --- /dev/null +++ b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java @@ -0,0 +1,71 @@ +package best.lolicon.felis.velocity; + +import best.lolicon.felis.link.ApiStats; + +import java.util.concurrent.atomic.AtomicLongArray; + +/** + * ProxyStats counts the proxy-side failures that each already get a warning line, so + * an operator can see their rate without grepping: calls the bounded pool refused, + * join-events that failed or were dropped (each one leaves the reaper blind to a real + * join and skips an allowlist append), transfers that did not connect, and server-list + * refreshes that failed. {@link #window()} returns what changed since the previous + * window; {@link #line} folds that and felis-api's own window into the periodic log + * line. + */ +final class ProxyStats { + enum Event { + POOL_REFUSED("busy refusals"), + JOIN_EVENT_FAILED("join-events failed"), + JOIN_EVENT_DROPPED("join-events dropped"), + TRANSFER_FAILED("transfers failed"), + REFRESH_FAILED("server-list refreshes failed"); + + final String label; + + Event(String label) { + this.label = label; + } + } + + private static final Event[] EVENTS = Event.values(); + private final AtomicLongArray counts = new AtomicLongArray(EVENTS.length); + private final long[] lastWindow = new long[EVENTS.length]; + + void count(Event e) { + counts.incrementAndGet(e.ordinal()); + } + + long total(Event e) { + return counts.get(e.ordinal()); + } + + /** window returns each event's count since the previous call, indexed by ordinal. */ + synchronized long[] window() { + long[] delta = new long[EVENTS.length]; + for (int i = 0; i < EVENTS.length; i++) { + long now = counts.get(i); + delta[i] = now - lastWindow[i]; + lastWindow[i] = now; + } + return delta; + } + + /** + * line is the periodic health line for one window, or null when the window saw no + * felis-api call, no failure and nobody waiting (an idle proxy logs nothing). + */ + static String line(long minutes, ApiStats.Snapshot api, long[] events, int waiting) { + boolean any = api.calls > 0 || waiting > 0; + StringBuilder sb = new StringBuilder(); + for (Event e : EVENTS) { + long n = events[e.ordinal()]; + any |= n > 0; + sb.append(", ").append(e.label).append('=').append(n); + } + if (!any) { + return null; + } + return "Felis: last " + minutes + " min: felis-api " + api.summary() + sb + ", waiting now=" + waiting; + } +} diff --git a/plugins/velocity/src/main/java/best/lolicon/felis/velocity/WaitingRouter.java b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/WaitingRouter.java index 59985e4..74c8087 100644 --- a/plugins/velocity/src/main/java/best/lolicon/felis/velocity/WaitingRouter.java +++ b/plugins/velocity/src/main/java/best/lolicon/felis/velocity/WaitingRouter.java @@ -349,15 +349,22 @@ public final class WaitingRouter { } catch (LinkException e) { // A lost join-event leaves the reaper blind to real activity and skips // the allowlist append, so it is an operator-visible failure. + plugin.stats().count(ProxyStats.Event.JOIN_EVENT_FAILED); log.warn("Felis: join-event for {} on {} failed (status={}): {}", id, name, e.statusCode(), e.getMessage()); } }); if (!taken) { + plugin.stats().count(ProxyStats.Event.JOIN_EVENT_DROPPED); log.warn("Felis: join-event for {} on {} dropped: the felis-api call queue is full", id, name); } } + /** waitingCount is how many players are parked for a backend right now. */ + int waitingCount() { + return waiting.size(); + } + /** tick drains the waiting queue; the plugin schedules it on the async pool. */ void tick() { if (waiting.isEmpty() || !ticking.compareAndSet(false, true)) { @@ -556,6 +563,7 @@ public final class WaitingRouter { private void transfer(Player player, String serverName, RegisteredServer backend) { player.createConnectionRequest(backend).connect().whenComplete((result, err) -> { if (err != null || (result != null && !result.isSuccessful())) { + plugin.stats().count(ProxyStats.Event.TRANSFER_FAILED); log.warn("Felis: transfer of {} to {} failed: {}", player.getUniqueId(), serverName, err != null ? err.toString() : result.getStatus()); player.sendMessage(Component.text( diff --git a/plugins/velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java b/plugins/velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java new file mode 100644 index 0000000..ac74ee5 --- /dev/null +++ b/plugins/velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java @@ -0,0 +1,92 @@ +package best.lolicon.felis.velocity; + +import best.lolicon.felis.link.ApiStats; +import best.lolicon.felis.link.FelisApiClient; +import best.lolicon.felis.link.LinkConfig; +import best.lolicon.felis.link.LinkException; + +import java.io.IOException; +import java.net.InetAddress; +import java.net.ServerSocket; +import java.util.UUID; + +/** + * ProxyStatsTest checks the proxy's failure counters: windows never overlap, totals + * keep growing, and the periodic line names every counter with its window value and + * stays silent for an idle window. Framework free: a failed assertion throws. + * + *

Run: {@code javac -d shared/src/main/java/best/lolicon/felis/link/*.java + * velocity/src/main/java/best/lolicon/felis/velocity/ProxyStats.java + * velocity/test/best/lolicon/felis/velocity/ProxyStatsTest.java && java -cp + * best.lolicon.felis.velocity.ProxyStatsTest}. + */ +public final class ProxyStatsTest { + + private static int checks; + + public static void main(String[] args) throws IOException { + ProxyStats s = new ProxyStats(); + s.count(ProxyStats.Event.JOIN_EVENT_FAILED); + s.count(ProxyStats.Event.JOIN_EVENT_FAILED); + s.count(ProxyStats.Event.TRANSFER_FAILED); + s.count(ProxyStats.Event.REFRESH_FAILED); + s.count(ProxyStats.Event.REFRESH_FAILED); + s.count(ProxyStats.Event.REFRESH_FAILED); + + long[] w1 = s.window(); + assertEq("w1 pool refused", 0L, w1[ProxyStats.Event.POOL_REFUSED.ordinal()]); + assertEq("w1 join failed", 2L, w1[ProxyStats.Event.JOIN_EVENT_FAILED.ordinal()]); + assertEq("w1 join dropped", 0L, w1[ProxyStats.Event.JOIN_EVENT_DROPPED.ordinal()]); + assertEq("w1 transfer failed", 1L, w1[ProxyStats.Event.TRANSFER_FAILED.ordinal()]); + assertEq("w1 refresh failed", 3L, w1[ProxyStats.Event.REFRESH_FAILED.ordinal()]); + + s.count(ProxyStats.Event.POOL_REFUSED); + s.count(ProxyStats.Event.JOIN_EVENT_FAILED); + long[] w2 = s.window(); + assertEq("w2 pool refused", 1L, w2[ProxyStats.Event.POOL_REFUSED.ordinal()]); + assertEq("w2 join failed (only the new one)", 1L, w2[ProxyStats.Event.JOIN_EVENT_FAILED.ordinal()]); + assertEq("w2 refresh failed (none new)", 0L, w2[ProxyStats.Event.REFRESH_FAILED.ordinal()]); + assertEq("total join failed", 3L, s.total(ProxyStats.Event.JOIN_EVENT_FAILED)); + assertEq("total refresh failed", 3L, s.total(ProxyStats.Event.REFRESH_FAILED)); + + long[] idle = s.window(); + ApiStats noCalls = new ApiStats(); + assertEq("idle window logs nothing", null, ProxyStats.line(10, noCalls.window(), idle, 0)); + assertEq("someone waiting is worth a line", + "Felis: last 10 min: felis-api calls=0 (no answer=0, 4xx=0, 5xx=0, retried=0), avg=0 ms, max=0 ms" + + ", busy refusals=0, join-events failed=0, join-events dropped=0, transfers failed=0" + + ", server-list refreshes failed=0, waiting now=2", + ProxyStats.line(10, noCalls.window(), idle, 2)); + assertEq("a failure alone is worth a line", + "Felis: last 10 min: felis-api calls=0 (no answer=0, 4xx=0, 5xx=0, retried=0), avg=0 ms, max=0 ms" + + ", busy refusals=1, join-events failed=1, join-events dropped=0, transfers failed=0" + + ", server-list refreshes failed=0, waiting now=0", + ProxyStats.line(10, noCalls.window(), w2, 0)); + + // One felis-api call and nothing else is still worth a line: a single POST to a + // port nobody listens on (POST is never retried, so exactly one attempt). + int closed; + try (ServerSocket probe = new ServerSocket(0, 1, InetAddress.getLoopbackAddress())) { + closed = probe.getLocalPort(); + } + FelisApiClient api = new FelisApiClient(new LinkConfig("http://127.0.0.1:" + closed, "t")); + try { + api.reportJoin("lobby", UUID.fromString("00000000-0000-0000-0000-000000000001")); + throw new AssertionError("reportJoin to a closed port succeeded"); + } catch (LinkException expected) { + // the call failed without an answer, which is what we want counted + } + String one = ProxyStats.line(10, api.stats().window(), s.window(), 0); + assertEq("one call alone is worth a line", true, one != null && one.startsWith( + "Felis: last 10 min: felis-api calls=1 (no answer=1, 4xx=0, 5xx=0, retried=0), avg=")); + + System.out.println("ProxyStatsTest OK (" + checks + " checks)"); + } + + private static void assertEq(String what, Object want, Object got) { + if (want == null ? got != null : !want.equals(got)) { + throw new AssertionError(what + ": got " + got + ", want " + want); + } + checks++; + } +}