This is an automated email from the ASF dual-hosted git repository.
Aias00 pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/shenyu.git
The following commit(s) were added to refs/heads/master by this push:
new a186c1cd6d fix(log): reduce routine matching and configuration-sync
log volume (#7643) (#7663)
a186c1cd6d is described below
commit a186c1cd6d305361097ae9430eee36a080351bb0
Author: konlue <[email protected]>
AuthorDate: Sat Oct 17 20:47:34 2026 +0800
fix(log): reduce routine matching and configuration-sync log volume (#7643)
(#7663)
* fix(plugin-base): route match-success logging through the logged flag
Two cases where the code contradicted itself.
#7643's scope asks for routine match-success diagnostics to sit behind
DEBUG or the
explicit matching-log setting, without duplicating messages. printLog
already sits
behind the setting: it checks selectorData.getLogged() and
ruleData.getLoged() and
carries the selector or rule name. defaultMatchSelector and
defaultMatchRule logged
the same event a second time with no switch at all, so a user who had not
enabled
logging still received one INFO line per matched request while the
cache-hit path
stayed quiet. Both lines arrived from the same refactor (#4578) that
introduced
printLog, and both are unreachable-as-documented once printLog runs, so
they are
removed rather than demoted -- demoting them to DEBUG would have left two
DEBUG lines
describing one match, which is the duplication the scope warns against. The
surviving
INFO line is the one that names the selector or rule.
ShenyuWebsocketClient#handleResult logged the entire raw frame at INFO with
no switch
and no level check, emitted before the GsonUtils.fromJson call, so a
malformed frame
was written out in full before the catch discarded it. The payload moves to
DEBUG
unchanged and INFO carries only groupType, eventType, namespaceId and
payload size,
logged after parsing so the group type is available. Parse failures keep
their WARN.
The two removed lines cost 51 and 44 bytes of message text per match (95
bytes before
logback's line prefix) for a default plugin name; a deployment matching on
every
request wrote that much per request to INFO regardless of the logged
setting. That
figure is derived from the message constants, not measured, and I have no
controlled
environment here to report a before/after rate, an allocation rate or a p99
-- the
repo has no JMH infrastructure and I don't have a bare-metal Linux box, so
I am not
going to present numbers I can't defend.
Tests cover both directions of the setting and the routing result: two
cases assert no
selector or rule line reaches INFO when the flag is false, two assert
exactly one line
does reach INFO when it is true and that it is the name-carrying one, and
one asserts
doExecute still receives the same selector and rule. Removing the two
getLogged and
getLoged guards makes the disabled cases fail, so they do pin the
behaviour. The
exactly-once assertions also pin the de-duplication. logback-classic is
added with
test scope, following shenyu-plugin-wasm-api and shenyu-sync-data-http,
since this
module had only slf4j-api on the test classpath.
No new configuration flag and no change to matching or routing logic.
Fixes #7643
* fix(sync): report websocket payload size in bytes
Review follow-ups on the log-noise change:
- ShenyuWebsocketClient: count the payload as UTF-8 bytes instead of
UTF-16 chars, so the INFO line's "bytes" unit stays accurate for
non-ASCII configuration content.
- LogCapture: drop the unused originalLevel field and its no-op restore
(the logger level is never modified during capture), and add the
missing trailing newline.
AbstractShenyuPluginTest 13/13, ShenyuWebsocketClientTest 34/34.
---
shenyu-plugin/shenyu-plugin-base/pom.xml | 5 +
.../shenyu/plugin/base/AbstractShenyuPlugin.java | 3 -
.../plugin/base/AbstractShenyuPluginTest.java | 107 +++++++++++++++++++++
.../org/apache/shenyu/plugin/base/LogCapture.java | 78 +++++++++++++++
.../websocket/client/ShenyuWebsocketClient.java | 7 +-
5 files changed, 196 insertions(+), 4 deletions(-)
diff --git a/shenyu-plugin/shenyu-plugin-base/pom.xml
b/shenyu-plugin/shenyu-plugin-base/pom.xml
index a34194e5e7..b200f17a99 100644
--- a/shenyu-plugin/shenyu-plugin-base/pom.xml
+++ b/shenyu-plugin/shenyu-plugin-base/pom.xml
@@ -59,5 +59,10 @@
<groupId>com.google.re2j</groupId>
<artifactId>re2j</artifactId>
</dependency>
+ <dependency>
+ <groupId>ch.qos.logback</groupId>
+ <artifactId>logback-classic</artifactId>
+ <scope>test</scope>
+ </dependency>
</dependencies>
</project>
diff --git
a/shenyu-plugin/shenyu-plugin-base/src/main/java/org/apache/shenyu/plugin/base/AbstractShenyuPlugin.java
b/shenyu-plugin/shenyu-plugin-base/src/main/java/org/apache/shenyu/plugin/base/AbstractShenyuPlugin.java
index 4b5a467f0c..41eaf4dff6 100644
---
a/shenyu-plugin/shenyu-plugin-base/src/main/java/org/apache/shenyu/plugin/base/AbstractShenyuPlugin.java
+++
b/shenyu-plugin/shenyu-plugin-base/src/main/java/org/apache/shenyu/plugin/base/AbstractShenyuPlugin.java
@@ -28,7 +28,6 @@ import org.apache.shenyu.common.dto.RuleData;
import org.apache.shenyu.common.dto.SelectorData;
import org.apache.shenyu.common.enums.MatchModeEnum;
import org.apache.shenyu.common.enums.SelectorTypeEnum;
-import org.apache.shenyu.common.utils.LogUtils;
import org.apache.shenyu.plugin.api.ShenyuPlugin;
import org.apache.shenyu.plugin.api.ShenyuPluginChain;
import org.apache.shenyu.plugin.api.utils.SpringBeanUtils;
@@ -292,7 +291,6 @@ public abstract class AbstractShenyuPlugin implements
ShenyuPlugin {
Pair<Boolean, SelectorData> matchSelectorPair =
matchSelector(exchange, selectors);
SelectorData selectorData = matchSelectorPair.getRight();
if (Objects.nonNull(selectorData)) {
- LogUtils.info(LOG, "{} selector match success from default
strategy", named());
// cache selector data
if (matchSelectorPair.getLeft()) {
cacheSelectorData(path, selectorData);
@@ -312,7 +310,6 @@ public abstract class AbstractShenyuPlugin implements
ShenyuPlugin {
Pair<Boolean, RuleData> matchRulePair = matchRule(exchange, rules);
RuleData ruleData = matchRulePair.getRight();
if (Objects.nonNull(ruleData)) {
- LOG.info("{} rule match path from default strategy", named());
// cache rule data
if (matchRulePair.getLeft()) {
cacheRuleData(path, ruleData);
diff --git
a/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/AbstractShenyuPluginTest.java
b/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/AbstractShenyuPluginTest.java
index e86c4d0091..d289489944 100644
---
a/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/AbstractShenyuPluginTest.java
+++
b/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/AbstractShenyuPluginTest.java
@@ -41,7 +41,10 @@ import reactor.test.StepVerifier;
import java.util.Collections;
import java.util.List;
+import java.util.stream.Collectors;
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertTrue;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.spy;
import static org.mockito.Mockito.verify;
@@ -248,6 +251,110 @@ public final class AbstractShenyuPluginTest {
verify(testShenyuPlugin).doExecute(exchange, shenyuPluginChain,
selectorData, ruleData);
}
+ @Test
+ public void defaultStrategySelectorMatchShouldNotLogWhenLoggingDisabled() {
+ List<ConditionData> conditionDataList =
Collections.singletonList(conditionData);
+ this.ruleData.setConditionDataList(conditionDataList);
+ this.ruleData.setMatchMode(0);
+ this.selectorData.setSort(1);
+ this.selectorData.setMatchMode(0);
+ this.selectorData.setLogged(false);
+ this.selectorData.setConditionList(conditionDataList);
+ BaseDataCache.getInstance().cachePluginData(pluginData);
+ BaseDataCache.getInstance().cacheSelectData(selectorData);
+ BaseDataCache.getInstance().cacheRuleData(ruleData);
+ try (LogCapture capture =
LogCapture.attach(AbstractShenyuPlugin.class)) {
+ StepVerifier.create(testShenyuPlugin.execute(exchange,
shenyuPluginChain)).expectSubscription().verifyComplete();
+ assertTrue(capture.infoMessages().stream().noneMatch(message ->
message.contains("selector")),
+ "no selector match line may reach INFO when the selector's
logged flag is false, got: " + capture.infoMessages());
+ }
+ }
+
+ @Test
+ public void
defaultStrategySelectorMatchShouldLogExactlyOnceWhenLoggingEnabled() {
+ List<ConditionData> conditionDataList =
Collections.singletonList(conditionData);
+ this.ruleData.setConditionDataList(conditionDataList);
+ this.ruleData.setMatchMode(0);
+ this.selectorData.setSort(1);
+ this.selectorData.setMatchMode(0);
+ this.selectorData.setLogged(true);
+ this.selectorData.setConditionList(conditionDataList);
+ BaseDataCache.getInstance().cachePluginData(pluginData);
+ BaseDataCache.getInstance().cacheSelectData(selectorData);
+ BaseDataCache.getInstance().cacheRuleData(ruleData);
+ try (LogCapture capture =
LogCapture.attach(AbstractShenyuPlugin.class)) {
+ StepVerifier.create(testShenyuPlugin.execute(exchange,
shenyuPluginChain)).expectSubscription().verifyComplete();
+ List<String> selectorLines = capture.infoMessages().stream()
+ .filter(message -> message.contains("selector"))
+ .collect(Collectors.toList());
+ assertEquals(1, selectorLines.size(),
+ "exactly one selector match line is expected at INFO when
logged is true, got: " + selectorLines);
+ assertTrue(selectorLines.get(0).contains("selector success match"),
+ "the surviving line should be the one that carries the
selector name, got: " + selectorLines.get(0));
+ }
+ }
+
+ @Test
+ public void defaultStrategyRuleMatchShouldNotLogWhenLoggingDisabled() {
+ List<ConditionData> conditionDataList =
Collections.singletonList(conditionData);
+ this.ruleData.setConditionDataList(conditionDataList);
+ this.ruleData.setMatchMode(0);
+ this.ruleData.setLoged(false);
+ this.selectorData.setSort(1);
+ this.selectorData.setMatchMode(0);
+ this.selectorData.setLogged(false);
+ this.selectorData.setConditionList(conditionDataList);
+ BaseDataCache.getInstance().cachePluginData(pluginData);
+ BaseDataCache.getInstance().cacheSelectData(selectorData);
+ BaseDataCache.getInstance().cacheRuleData(ruleData);
+ try (LogCapture capture =
LogCapture.attach(AbstractShenyuPlugin.class)) {
+ StepVerifier.create(testShenyuPlugin.execute(exchange,
shenyuPluginChain)).expectSubscription().verifyComplete();
+ assertTrue(capture.infoMessages().stream().noneMatch(message ->
message.contains("rule")),
+ "no rule match line may reach INFO when the rule's loged
flag is false, got: " + capture.infoMessages());
+ }
+ }
+
+ @Test
+ public void
defaultStrategyRuleMatchShouldLogExactlyOnceWhenLoggingEnabled() {
+ List<ConditionData> conditionDataList =
Collections.singletonList(conditionData);
+ this.ruleData.setConditionDataList(conditionDataList);
+ this.ruleData.setMatchMode(0);
+ this.ruleData.setLoged(true);
+ this.selectorData.setSort(1);
+ this.selectorData.setMatchMode(0);
+ this.selectorData.setLogged(true);
+ this.selectorData.setConditionList(conditionDataList);
+ BaseDataCache.getInstance().cachePluginData(pluginData);
+ BaseDataCache.getInstance().cacheSelectData(selectorData);
+ BaseDataCache.getInstance().cacheRuleData(ruleData);
+ try (LogCapture capture =
LogCapture.attach(AbstractShenyuPlugin.class)) {
+ StepVerifier.create(testShenyuPlugin.execute(exchange,
shenyuPluginChain)).expectSubscription().verifyComplete();
+ List<String> ruleLines = capture.infoMessages().stream()
+ .filter(message -> message.contains("rule"))
+ .collect(Collectors.toList());
+ assertEquals(1, ruleLines.size(),
+ "exactly one rule match line is expected at INFO when
loged is true, got: " + ruleLines);
+ assertTrue(ruleLines.get(0).contains("rule success match"),
+ "the surviving line should be the one that carries the
rule name, got: " + ruleLines.get(0));
+ }
+ }
+
+ @Test
+ public void defaultStrategyMatchLogsShouldNotChangeRoutingResults() {
+ List<ConditionData> conditionDataList =
Collections.singletonList(conditionData);
+ this.ruleData.setConditionDataList(conditionDataList);
+ this.ruleData.setMatchMode(0);
+ this.selectorData.setSort(1);
+ this.selectorData.setMatchMode(0);
+ this.selectorData.setLogged(true);
+ this.selectorData.setConditionList(conditionDataList);
+ BaseDataCache.getInstance().cachePluginData(pluginData);
+ BaseDataCache.getInstance().cacheSelectData(selectorData);
+ BaseDataCache.getInstance().cacheRuleData(ruleData);
+ StepVerifier.create(testShenyuPlugin.execute(exchange,
shenyuPluginChain)).expectSubscription().verifyComplete();
+ verify(testShenyuPlugin).doExecute(exchange, shenyuPluginChain,
selectorData, ruleData);
+ }
+
@AfterEach
public void clear() {
MatchDataCache.getInstance().cleanSelectorData();
diff --git
a/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/LogCapture.java
b/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/LogCapture.java
new file mode 100644
index 0000000000..5d86210fd3
--- /dev/null
+++
b/shenyu-plugin/shenyu-plugin-base/src/test/java/org/apache/shenyu/plugin/base/LogCapture.java
@@ -0,0 +1,78 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.shenyu.plugin.base;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import org.slf4j.LoggerFactory;
+
+import java.util.List;
+import java.util.stream.Collectors;
+
+/**
+ * Captures log events emitted by a single logger, so that a test can assert on
+ * what a code path did (or did not) log.
+ *
+ * <p>The appender is detached and stopped when the instance is closed, so a
+ * capture never leaks into subsequent tests running in the same JVM.
+ */
+final class LogCapture implements AutoCloseable {
+
+ private final Logger logger;
+
+ private final ListAppender<ILoggingEvent> appender;
+
+ private LogCapture(final Logger logger) {
+ this.logger = logger;
+ this.appender = new ListAppender<>();
+ this.appender.setContext(logger.getLoggerContext());
+ this.appender.start();
+ logger.addAppender(this.appender);
+ }
+
+ /**
+ * Attach a capture to the logger of the given type.
+ *
+ * @param type the class whose logger should be captured
+ * @return the capture, to be used as a try-with-resources resource
+ */
+ static LogCapture attach(final Class<?> type) {
+ Logger logger = (Logger) LoggerFactory.getLogger(type);
+ return new LogCapture(logger);
+ }
+
+ /**
+ * All formatted messages that were logged at INFO level during the
capture.
+ *
+ * @return the INFO messages
+ */
+ List<String> infoMessages() {
+ return appender.list.stream()
+ .filter(event -> Level.INFO.equals(event.getLevel()))
+ .map(ILoggingEvent::getFormattedMessage)
+ .collect(Collectors.toList());
+ }
+
+ @Override
+ public void close() {
+ logger.detachAppender(appender);
+ appender.stop();
+ }
+}
diff --git
a/shenyu-sync-data-center/shenyu-sync-data-websocket/src/main/java/org/apache/shenyu/plugin/sync/data/websocket/client/ShenyuWebsocketClient.java
b/shenyu-sync-data-center/shenyu-sync-data-websocket/src/main/java/org/apache/shenyu/plugin/sync/data/websocket/client/ShenyuWebsocketClient.java
index 64522afd22..2ad99b3569 100644
---
a/shenyu-sync-data-center/shenyu-sync-data-websocket/src/main/java/org/apache/shenyu/plugin/sync/data/websocket/client/ShenyuWebsocketClient.java
+++
b/shenyu-sync-data-center/shenyu-sync-data-websocket/src/main/java/org/apache/shenyu/plugin/sync/data/websocket/client/ShenyuWebsocketClient.java
@@ -31,6 +31,7 @@ import org.apache.shenyu.common.timer.TimerTask;
import org.apache.shenyu.common.timer.WheelTimerFactory;
import org.apache.shenyu.common.utils.GsonUtils;
import org.apache.shenyu.common.utils.JsonUtils;
+import org.apache.shenyu.common.utils.LogUtils;
import org.apache.shenyu.common.utils.SystemInfoUtils;
import
org.apache.shenyu.plugin.sync.data.websocket.handler.WebsocketDataHandler;
import org.apache.shenyu.sync.data.api.AuthDataSubscriber;
@@ -49,6 +50,7 @@ import
org.apache.shenyu.common.concurrent.ShenyuThreadFactory;
import org.apache.shenyu.common.concurrent.ShenyuThreadPoolExecutor;
import java.net.URI;
+import java.nio.charset.StandardCharsets;
import java.util.List;
import java.util.Map;
import java.util.Objects;
@@ -436,7 +438,7 @@ public final class ShenyuWebsocketClient extends
WebSocketClient {
* @param result result
*/
private void handleResult(final String result) {
- LOG.info("server [{}] handleResult({})", this.getURI().toString(),
result);
+ LogUtils.debug(LOG, "server [{}] handleResult({})",
this.getURI().toString(), result);
WebsocketData<?> websocketData;
try {
websocketData = GsonUtils.getInstance().fromJson(result,
WebsocketData.class);
@@ -447,6 +449,9 @@ public final class ShenyuWebsocketClient extends
WebSocketClient {
LOG.warn("Failed to parse websocket message from server[{}], the
message will be ignored", this.getURI(), ex);
return;
}
+ LOG.info("server [{}] received config message: groupType: {},
eventType: {}, namespaceId: {}, size: {} bytes",
+ this.getURI(), websocketData.getGroupType(),
websocketData.getEventType(),
+ websocketData.getNamespaceId(),
result.getBytes(StandardCharsets.UTF_8).length);
ConfigGroupEnum groupEnum;
String eventType;
String json;
