fix(api): harden load rejection logging

contrueCT · contrueCT · commit d5d7ce013135 · 2026-03-23T22:18:10.000+08:00
diff --git a/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/LoadDetectFilter.java b/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/LoadDetectFilter.java
@@ -74,14 +74,24 @@ public static boolean isWhiteAPI(ContainerRequestContext context) {
         return WHITE_API_LIST.contains(rootPath);
     }
 
-    private static boolean gcIfNeeded() {
+    protected boolean gcIfNeeded() {
         if (GC_RATE_LIMITER.tryAcquire(1)) {
             System.gc();
             return true;
         }
         return false;
     }
 
+    protected boolean allowRejectLog() {
+        return REJECT_LOG_RATE_LIMITER.tryAcquire();
+    }
+
+    protected void logRejectWarning(String message, Object... args) {
+        if (this.allowRejectLog()) {
+            LOG.warn(message, args);
+        }
+    }
+
     @Override
     public void filter(ContainerRequestContext context) {
         if (LoadDetectFilter.isWhiteAPI(context)) {
@@ -95,12 +105,10 @@ public void filter(ContainerRequestContext context) {
         // There will be a thread doesn't work, dedicated to statistics
         int currentLoad = load.incrementAndGet();
         if (currentLoad >= maxWorkerThreads) {
-            if (REJECT_LOG_RATE_LIMITER.tryAcquire()) {
-                LOG.warn("Rejected request due to high worker load, method={}, path={}, " +
-                         "currentLoad={}, maxWorkerThreads={}",
-                         context.getMethod(), context.getUriInfo().getPath(),
-                         currentLoad, maxWorkerThreads);
-            }
+            this.logRejectWarning("Rejected request due to high worker load, method={}, path={}, " +
+                                  "currentLoad={}, maxWorkerThreads={}",
+                                  context.getMethod(), context.getUriInfo().getPath(),
+                                  currentLoad, maxWorkerThreads);
             throw new ServiceUnavailableException(String.format(
                     "The server is too busy to process the request, " +
                     "you can config %s to adjust it or try again later",
@@ -113,17 +121,17 @@ public void filter(ContainerRequestContext context) {
         long presumableFreeMem = (Runtime.getRuntime().maxMemory() -
                                   allocatedMem) / Bytes.MB;
         if (presumableFreeMem < minFreeMemory) {
-            boolean gcTriggered = gcIfNeeded();
+            boolean gcTriggered = this.gcIfNeeded();
             long allocatedMemAfterCheck = Runtime.getRuntime().totalMemory() -
                                           Runtime.getRuntime().freeMemory();
             long recheckedFreeMem = (Runtime.getRuntime().maxMemory() -
                                      allocatedMemAfterCheck) / Bytes.MB;
-            LOG.warn("Rejected request due to low free memory, method={}, path={}, " +
-                     "presumableFreeMemMB={}, recheckedFreeMemMB={}, gcTriggered={}, " +
-                     "minFreeMemoryMB={}",
-                     context.getMethod(), context.getUriInfo().getPath(),
-                     presumableFreeMem, recheckedFreeMem, gcTriggered,
-                     minFreeMemory);
+            this.logRejectWarning("Rejected request due to low free memory, method={}, path={}, " +
+                                  "presumableFreeMemMB={}, recheckedFreeMemMB={}, gcTriggered={}, " +
+                                  "minFreeMemoryMB={}",
+                                  context.getMethod(), context.getUriInfo().getPath(),
+                                  presumableFreeMem, recheckedFreeMem, gcTriggered,
+                                  minFreeMemory);
             throw new ServiceUnavailableException(String.format(
                     "The server available memory %s(MB) is below than " +
                     "threshold %s(MB) and can't process the request, " +
diff --git a/hugegraph-server/hugegraph-test/src/main/java/org/apache/hugegraph/unit/api/filter/LoadDetectFilterTest.java b/hugegraph-server/hugegraph-test/src/main/java/org/apache/hugegraph/unit/api/filter/LoadDetectFilterTest.java
@@ -17,6 +17,10 @@
 
 package org.apache.hugegraph.unit.api.filter;
 
+import java.io.Serializable;
+import java.util.ArrayDeque;
+import java.util.ArrayList;
+import java.util.Deque;
 import java.util.List;
 import java.util.stream.Collectors;
 
@@ -29,6 +33,15 @@
 import org.apache.hugegraph.testutil.Assert;
 import org.apache.hugegraph.testutil.Whitebox;
 import org.apache.hugegraph.unit.BaseUnitTest;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.core.Filter;
+import org.apache.logging.log4j.core.Layout;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.Logger;
+import org.apache.logging.log4j.core.appender.AbstractAppender;
+import org.apache.logging.log4j.core.config.Property;
+import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
 import org.mockito.Mockito;
@@ -41,25 +54,38 @@
 
 public class LoadDetectFilterTest extends BaseUnitTest {
 
+    private static final Logger TEST_LOGGER =
+            (Logger) LogManager.getLogger(LoadDetectFilter.class);
+
     private LoadDetectFilter loadDetectFilter;
     private ContainerRequestContext requestContext;
     private UriInfo uriInfo;
     private WorkLoad workLoad;
+    private TestAppender testAppender;
 
     @Before
     public void setup() {
         this.requestContext = Mockito.mock(ContainerRequestContext.class);
         this.uriInfo = Mockito.mock(UriInfo.class);
         this.workLoad = new WorkLoad();
+        this.testAppender = new TestAppender();
+        this.testAppender.start();
+        TEST_LOGGER.addAppender(this.testAppender);
 
         Mockito.when(this.requestContext.getUriInfo()).thenReturn(this.uriInfo);
         Mockito.when(this.requestContext.getMethod()).thenReturn("GET");
 
-        this.loadDetectFilter = new LoadDetectFilter();
+        this.loadDetectFilter = new TestLoadDetectFilter();
         this.setLoadProvider(this.workLoad);
         this.setConfigProvider(createConfig(8, 0));
     }
 
+    @After
+    public void teardown() {
+        TEST_LOGGER.removeAppender(this.testAppender);
+        this.testAppender.stop();
+    }
+
     @Test
     public void testFilter_WhiteListPathIgnored() {
         setupPath("", List.of(""));
@@ -68,6 +94,7 @@ public void testFilter_WhiteListPathIgnored() {
         this.loadDetectFilter.filter(this.requestContext);
 
         Assert.assertEquals(1, this.workLoad.get().get());
+        Assert.assertTrue(this.testAppender.events().isEmpty());
     }
 
     @Test
@@ -85,13 +112,19 @@ public void testFilter_RejectsWhenWorkerLoadIsTooHigh() {
                               exception.getMessage());
         Assert.assertContains(ServerOptions.MAX_WORKER_THREADS.name(),
                               exception.getMessage());
+        Assert.assertEquals(1, this.testAppender.events().size());
+        this.assertWarnLogContains("Rejected request due to high worker load");
+        this.assertWarnLogContains("method=GET");
+        this.assertWarnLogContains("path=graphs/hugegraph/vertices");
+        this.assertWarnLogContains("currentLoad=2");
     }
 
     @Test
     public void testFilter_RejectsWhenFreeMemoryIsTooLow() {
         setupPath("graphs/hugegraph/vertices",
                   List.of("graphs", "hugegraph", "vertices"));
         this.setConfigProvider(createConfig(8, Integer.MAX_VALUE));
+        this.setGcTriggered(false);
 
         ServiceUnavailableException exception = (ServiceUnavailableException) Assert.assertThrows(
                 ServiceUnavailableException.class,
@@ -101,6 +134,11 @@ public void testFilter_RejectsWhenFreeMemoryIsTooLow() {
                               exception.getMessage());
         Assert.assertContains(ServerOptions.MIN_FREE_MEMORY.name(),
                               exception.getMessage());
+        Assert.assertEquals(1, this.testAppender.events().size());
+        this.assertWarnLogContains("Rejected request due to low free memory");
+        this.assertWarnLogContains("method=GET");
+        this.assertWarnLogContains("path=graphs/hugegraph/vertices");
+        this.assertWarnLogContains("gcTriggered=false");
     }
 
     @Test
@@ -112,6 +150,26 @@ public void testFilter_AllowsRequestWhenLoadAndMemoryAreHealthy() {
         this.loadDetectFilter.filter(this.requestContext);
 
         Assert.assertEquals(1, this.workLoad.get().get());
+        Assert.assertTrue(this.testAppender.events().isEmpty());
+    }
+
+    @Test
+    public void testFilter_RejectLogIsRateLimited() {
+        setupPath("graphs/hugegraph/vertices",
+                  List.of("graphs", "hugegraph", "vertices"));
+        this.setConfigProvider(createConfig(2, 0));
+        this.setAllowRejectLogs(true, false);
+
+        this.workLoad.incrementAndGet();
+        Assert.assertThrows(ServiceUnavailableException.class,
+                            () -> this.loadDetectFilter.filter(this.requestContext));
+
+        this.workLoad.get().set(1);
+        Assert.assertThrows(ServiceUnavailableException.class,
+                            () -> this.loadDetectFilter.filter(this.requestContext));
+
+        Assert.assertEquals(1, this.testAppender.events().size());
+        this.assertWarnLogContains("Rejected request due to high worker load");
     }
 
     private HugeConfig createConfig(int maxWorkerThreads, int minFreeMemory) {
@@ -144,4 +202,71 @@ private void setConfigProvider(HugeConfig config) {
         Whitebox.setInternalState(this.loadDetectFilter, "configProvider",
                                   (Provider<HugeConfig>) () -> config);
     }
+
+    private void setGcTriggered(boolean gcTriggered) {
+        ((TestLoadDetectFilter) this.loadDetectFilter).gcTriggered(gcTriggered);
+    }
+
+    private void setAllowRejectLogs(boolean... allowedLogs) {
+        ((TestLoadDetectFilter) this.loadDetectFilter).allowRejectLogs(allowedLogs);
+    }
+
+    private void assertWarnLogContains(String expectedContent) {
+        Assert.assertFalse(this.testAppender.events().isEmpty());
+        LogEvent event = this.testAppender.events().get(0);
+        Assert.assertEquals(Level.WARN, event.getLevel());
+        Assert.assertContains(expectedContent,
+                              event.getMessage().getFormattedMessage());
+    }
+
+    private static class TestLoadDetectFilter extends LoadDetectFilter {
+
+        private boolean gcTriggered;
+        private final Deque<Boolean> allowRejectLogs = new ArrayDeque<>();
+
+        public void gcTriggered(boolean gcTriggered) {
+            this.gcTriggered = gcTriggered;
+        }
+
+        public void allowRejectLogs(boolean... allowedLogs) {
+            this.allowRejectLogs.clear();
+            for (boolean allowedLog : allowedLogs) {
+                this.allowRejectLogs.addLast(allowedLog);
+            }
+        }
+
+        @Override
+        protected boolean gcIfNeeded() {
+            return this.gcTriggered;
+        }
+
+        @Override
+        protected boolean allowRejectLog() {
+            if (this.allowRejectLogs.isEmpty()) {
+                return true;
+            }
+            return this.allowRejectLogs.removeFirst();
+        }
+    }
+
+    private static class TestAppender extends AbstractAppender {
+
+        private final List<LogEvent> events;
+
+        protected TestAppender() {
+            super("LoadDetectFilterTestAppender", (Filter) null,
+                  (Layout<? extends Serializable>) null, false,
+                  Property.EMPTY_ARRAY);
+            this.events = new ArrayList<>();
+        }
+
+        @Override
+        public void append(LogEvent event) {
+            this.events.add(event.toImmutable());
+        }
+
+        public List<LogEvent> events() {
+            return this.events;
+        }
+    }
 }
