feat(plugins): 插件侧计数器与周期健康日志,Limbo/刷新失败按故障周期升级日志

This commit is contained in:
Lemon-miaow committed 2026-09-26 00:33:04 +08:00
1 parent fcf5c305ea
commit b65c2c00b3
13 files changed
+634 -17

No files matched your search

+30
View File
@@ -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=<id from the error>' kubectl -n felis logs deploy/felis-api | grep 'request_id=<id from the error>'
``` ```
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 ### Scraping
The series come from two processes. Both Services carry the The series come from two processes. Both Services carry the
+10
View File
@@ -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 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. 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) ## Lobby menu (§12)
The `paper/` module is the lobby's player-facing face for §27 scenario 10 The `paper/` module is the lobby's player-facing face for §27 scenario 10
@@ -8,6 +8,7 @@ import best.lolicon.felis.link.LinkCode;
import best.lolicon.felis.link.LinkConfig; import best.lolicon.felis.link.LinkConfig;
import best.lolicon.felis.link.LinkConfigLoader; import best.lolicon.felis.link.LinkConfigLoader;
import best.lolicon.felis.link.LinkException; import best.lolicon.felis.link.LinkException;
import best.lolicon.felis.link.OutageTracker;
import com.loohp.limbo.events.EventHandler; import com.loohp.limbo.events.EventHandler;
import com.loohp.limbo.events.Listener; 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; 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. // 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; 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 ---- // ---- readiness state ----
private final AtomicBoolean ready = new AtomicBoolean(false); 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" // Players whose release loop is running; the async link poll can observe "linked"
// twice before its cancellation lands, and the release must start once. // twice before its cancellation lands, and the release must start once.
private final Set<UUID> releasing = ConcurrentHashMap.newKeySet(); private final Set<UUID> 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 @Override
public void onEnable() { public void onEnable() {
@@ -324,7 +332,8 @@ public final class FelisLimboPlugin extends LimboPlugin implements Listener {
} catch (RuntimeException e) { } catch (RuntimeException e) {
// A client that refuses the book (rare) still gets the chat instructions // A client that refuses the book (rare) still gets the chat instructions
// below, so a book failure is not fatal to the flow. // 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] 绑定码 / Code: §6" + code.code());
player.sendMessage("§e[Felis] 用系统浏览器打开 §b" + url 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."); disconnectOnMain(id, "登录超时,请重连 / Login timed out. Please reconnect.");
return; return;
} }
boolean linked;
try { try {
if (apiClient.linkStatus(id)) { linked = apiClient.linkStatus(id);
getServer().getScheduler().runTask(this, () -> startRelease(id));
}
} catch (LinkException e) { } catch (LinkException e) {
// A transient poll failure is not fatal — keep trying until the deadline. // 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));
} }
} }
@@ -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";
}
}
}
@@ -54,6 +54,7 @@ public final class FelisApiClient {
private final LinkConfig config; private final LinkConfig config;
private final HttpClient http; private final HttpClient http;
private final ApiStats stats = new ApiStats();
public FelisApiClient(LinkConfig config) { public FelisApiClient(LinkConfig config) {
this.config = Objects.requireNonNull(config, "config"); this.config = Objects.requireNonNull(config, "config");
@@ -62,6 +63,11 @@ public final class FelisApiClient {
.build(); .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). */ /** listServers returns the lifecycle view of every MinecraftServer (GET /servers). */
public List<ServerView> listServers() throws LinkException { public List<ServerView> listServers() throws LinkException {
return ServerView.listFrom(getObject("/api/v1/servers", 200)); return ServerView.listFrom(getObject("/api/v1/servers", 200));
@@ -297,6 +303,7 @@ public final class FelisApiClient {
} catch (InterruptedException e) { } catch (InterruptedException e) {
throw interrupted(e); throw interrupted(e);
} }
stats.retried();
return expectObject(send(req), expect); 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<String> exchange(HttpRequest req) throws IOException, InterruptedException { private HttpResponse<String> exchange(HttpRequest req) throws IOException, InterruptedException {
return http.send(req, HttpResponse.BodyHandlers.ofString()); long start = System.nanoTime();
int status = 0;
try {
HttpResponse<String> 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 // A refused connection arrives as a ConnectException with no message; the class
@@ -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;
}
}
@@ -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 * 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 * 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 * 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.
* *
* <p>Run: {@code javac -d <out> shared/src/main/java/best/lolicon/felis/link/*.java * <p>Run: {@code javac -d <out> shared/src/main/java/best/lolicon/felis/link/*.java
* shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java && java -cp <out> * shared/test/best/lolicon/felis/link/FelisApiClientRetryTest.java && java -cp <out>
@@ -49,6 +50,8 @@ public final class FelisApiClientRetryTest {
getIsNotRetriedOnAClientError(api); getIsNotRetriedOnAClientError(api);
postIsNeverRetried(api); postIsNeverRetried(api);
timedOutGetIsCutOffAndNotRetried(api); timedOutGetIsCutOffAndNotRetried(api);
statsCountEveryAttempt(api);
statsArithmetic();
} finally { } finally {
stub.stop(0); stub.stop(0);
pool.shutdownNow(); pool.shutdownNow();
@@ -149,6 +152,61 @@ public final class FelisApiClientRetryTest {
assertEq("slow requests", 1, count("GET /api/v1/internal/servers/slow/status")); 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 ---- // ---- harness ----
interface Call { interface Call {
@@ -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.
*
* <p>Run: {@code javac -d <out> shared/src/main/java/best/lolicon/felis/link/*.java
* shared/test/best/lolicon/felis/link/OutageTrackerTest.java && java -cp <out>
* 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++;
}
}
+18 -1
View File
@@ -14,7 +14,10 @@
# after a dropped reply or a 502/503/504 and a POST never, the request timeout # 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 # 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 # 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 # 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 # outage routes on the last saved server list (and only until a fetch
# succeeds), /invite prompts cannot double-fire # succeeds), /invite prompts cannot double-fire
@@ -87,6 +90,12 @@ javac -d "$work/shared-classes" \
plugins/shared/test/best/lolicon/felis/link/LinkConfigLoaderTest.java plugins/shared/test/best/lolicon/felis/link/LinkConfigLoaderTest.java
java -cp "$work/shared-classes" best.lolicon.felis.link.LinkConfigLoaderTest 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)" echo "==> ControlPolicyTest (who may send what on felis:control, velocity)"
mkdir -p "$work/policy-classes" mkdir -p "$work/policy-classes"
javac -d "$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 plugins/velocity/test/best/lolicon/felis/velocity/ApiPoolTest.java
java -cp "$work/pool-classes" best.lolicon.felis.velocity.ApiPoolTest 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)" echo "==> InviteBookTest (/invite prompt store, velocity)"
mkdir -p "$work/velocity-classes" mkdir -p "$work/velocity-classes"
javac -d "$work/velocity-classes" \ javac -d "$work/velocity-classes" \
@@ -5,6 +5,7 @@ import best.lolicon.felis.link.LinkClient;
import best.lolicon.felis.link.LinkCode; import best.lolicon.felis.link.LinkCode;
import best.lolicon.felis.link.LinkException; import best.lolicon.felis.link.LinkException;
import best.lolicon.felis.link.OpLoginView; import best.lolicon.felis.link.OpLoginView;
import best.lolicon.felis.link.OutageTracker;
import best.lolicon.felis.link.ServerView; import best.lolicon.felis.link.ServerView;
import com.google.inject.Inject; 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_THREADS = 8;
private static final int API_QUEUE = 64; private static final int API_QUEUE = 64;
private static final long BUSY_LOG_INTERVAL_MILLIS = 60_000L; 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 ProxyServer proxy;
private final Logger logger; 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 FrameBudget commandBudget = new FrameBudget(5, 0.2, System::currentTimeMillis);
private final BoundedExecutor apiCalls; private final BoundedExecutor apiCalls;
private final AtomicLong lastBusyLog = new AtomicLong(); 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 FelisVelocityConfig config;
private LinkClient linkClient; private LinkClient linkClient;
@@ -169,6 +177,7 @@ public final class FelisVelocityPlugin {
refreshRegistrations(); refreshRegistrations();
repeating(REGISTRATION_REFRESH, this::refreshRegistrations); repeating(REGISTRATION_REFRESH, this::refreshRegistrations);
repeating(WAIT_POLL, router::tick); repeating(WAIT_POLL, router::tick);
repeating(STATS_INTERVAL, this::logStats);
this.routingActive = true; this.routingActive = true;
logger.info("Felis routing ready: rootDomain={}, login={}, lobby={}. /link, /felis and /invite registered.", 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)) { if (apiCalls.submit(task)) {
return true; return true;
} }
stats.count(ProxyStats.Event.POOL_REFUSED);
long now = System.currentTimeMillis(); long now = System.currentTimeMillis();
long last = lastBusyLog.get(); long last = lastBusyLog.get();
if (now - last >= BUSY_LOG_INTERVAL_MILLIS && lastBusyLog.compareAndSet(last, now)) { if (now - last >= BUSY_LOG_INTERVAL_MILLIS && lastBusyLog.compareAndSet(last, now)) {
@@ -214,6 +224,20 @@ public final class FelisVelocityPlugin {
return false; 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. */ /** async for a task a player is waiting on: a refusal is told to them at once. */
void async(Player player, Runnable task) { void async(Player player, Runnable task) {
if (!async(task)) { if (!async(task)) {
@@ -263,15 +287,30 @@ public final class FelisVelocityPlugin {
if (r.servers != null) { if (r.servers != null) {
registry.refresh(r.servers); registry.refresh(r.servers);
} }
if (r.restored) { if (r.failure == null) {
logger.warn("Felis: felis-api is unreachable at startup (status={}): {}; routing to the {} backends " if (refreshOutage.success() == OutageTracker.Report.RECOVERED) {
+ "in the saved server list until it answers.", logger.info("Felis: server list refresh recovered after {} failed attempts over {} s.",
r.failure.statusCode(), r.failure.getMessage(), r.servers.size()); refreshOutage.lastOutageFailures(), refreshOutage.lastOutageMillis() / 1000);
} else if (r.failure != null) { }
// Keep existing registrations on a control-plane blip (spec §11): a } else {
// transient failure must never deregister live backends. stats.count(ProxyStats.Event.REFRESH_FAILED);
logger.warn("Felis: server list refresh failed (status={}): {}; keeping current registrations.", OutageTracker.Report report = refreshOutage.failure();
r.failure.statusCode(), r.failure.getMessage()); 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) { if (r.fileError != null) {
logger.warn("Felis: saved server list {}: {}", r.failure == null ? "not written" : "not usable", 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("login", config.loginServer()));
source.sendMessage(field("lobby", config.lobbyServer())); source.sendMessage(field("lobby", config.lobbyServer()));
source.sendMessage(field("servers", String.valueOf(registry.all().size()))); 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( source.sendMessage(Component.text(
zh ? " /felis help 查看命令" : " /felis help for commands", NamedTextColor.GRAY)); zh ? " /felis help 查看命令" : " /felis help for commands", NamedTextColor.GRAY));
} }
@@ -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;
}
}
@@ -349,15 +349,22 @@ public final class WaitingRouter {
} catch (LinkException e) { } catch (LinkException e) {
// A lost join-event leaves the reaper blind to real activity and skips // A lost join-event leaves the reaper blind to real activity and skips
// the allowlist append, so it is an operator-visible failure. // 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={}): {}", log.warn("Felis: join-event for {} on {} failed (status={}): {}",
id, name, e.statusCode(), e.getMessage()); id, name, e.statusCode(), e.getMessage());
} }
}); });
if (!taken) { 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); 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. */ /** tick drains the waiting queue; the plugin schedules it on the async pool. */
void tick() { void tick() {
if (waiting.isEmpty() || !ticking.compareAndSet(false, true)) { if (waiting.isEmpty() || !ticking.compareAndSet(false, true)) {
@@ -556,6 +563,7 @@ public final class WaitingRouter {
private void transfer(Player player, String serverName, RegisteredServer backend) { private void transfer(Player player, String serverName, RegisteredServer backend) {
player.createConnectionRequest(backend).connect().whenComplete((result, err) -> { player.createConnectionRequest(backend).connect().whenComplete((result, err) -> {
if (err != null || (result != null && !result.isSuccessful())) { if (err != null || (result != null && !result.isSuccessful())) {
plugin.stats().count(ProxyStats.Event.TRANSFER_FAILED);
log.warn("Felis: transfer of {} to {} failed: {}", player.getUniqueId(), serverName, log.warn("Felis: transfer of {} to {} failed: {}", player.getUniqueId(), serverName,
err != null ? err.toString() : result.getStatus()); err != null ? err.toString() : result.getStatus());
player.sendMessage(Component.text( player.sendMessage(Component.text(
@@ -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.
*
* <p>Run: {@code javac -d <out> 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 <out>
* 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++;
}
}