From f1dce72f24a60733a484ec7fb6d57496673e4795 Mon Sep 17 00:00:00 2001 From: "shalk(xiao kun)" Date: Thu, 22 Oct 2026 11:57:18 +0800 Subject: [PATCH 1/2] feat(mockserver): bridge MockWebServer JUL logs to SLF4J okhttp's MockWebServer logs through java.util.logging directly, so its output bypassed slf4j/logback in test runs even when jul-to-slf4j was already on the classpath. Add an opt-in JUL to SLF4J bridge for MockWebServer logs: - Only the okhttp3.mockwebserver.MockWebServer logger is reconfigured, never the JUL root logger, so unrelated JUL handlers keep receiving records. - Skipped when jul-to-slf4j is absent or when the binding is slf4j-jdk14, which would turn the bridge into a JUL<->SLF4J logging loop. - Reference-counted per ApolloTestingServer instance, so concurrently running servers do not remove the bridge from under each other. - The ownership count only moves once the logger transition succeeded, so a failed acquire leaves the bridge reusable for later servers and a failed release stays retryable instead of poisoning the count. - The MockWebServer logger is retained strongly for the bridge's lifetime so GC cannot silently detach its handler during startup. start()/close() keep their behaviour; callers opt in with acquireJulBridge() and releaseJulBridge(). --- CHANGES.md | 1 + apollo-mockserver/pom.xml | 6 + .../mockserver/ApolloTestingServer.java | 30 ++ .../apollo/mockserver/JulSlf4jBridge.java | 189 +++++++++++ .../apollo/mockserver/JulSlf4jBridgeTest.java | 314 ++++++++++++++++++ 5 files changed, 540 insertions(+) create mode 100644 apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java create mode 100644 apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java diff --git a/CHANGES.md b/CHANGES.md index c18c8d75..80f4654d 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -8,6 +8,7 @@ Apollo Java 2.6.0 * [Fix Apollo client local cache fallback for Spring Boot 3 executable JARs](https://github.com/apolloconfig/apollo-java/pull/136) * [Support `extendInfo`/`parentAppId` in OpenAPI `getNamespace(s)` client calls](https://github.com/apolloconfig/apollo-java/pull/144) +* [Add an opt-in JUL to SLF4J bridge for MockWebServer logs](https://github.com/apolloconfig/apollo-java/pull/147) ------------------ All issues and pull requests are [here](https://github.com/apolloconfig/apollo-java/milestone/6?closed=1) diff --git a/apollo-mockserver/pom.xml b/apollo-mockserver/pom.xml index 9dec2d50..30bb0067 100644 --- a/apollo-mockserver/pom.xml +++ b/apollo-mockserver/pom.xml @@ -53,6 +53,12 @@ com.ctrip.framework.apollo apollo-client + + org.slf4j + jul-to-slf4j + 1.7.21 + true + com.squareup.okhttp3 mockwebserver diff --git a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java index e69acc45..4aae4d07 100644 --- a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java +++ b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java @@ -79,6 +79,8 @@ public class ApolloTestingServer implements AutoCloseable { private boolean closed; + private boolean bridgeAcquired; + static { try { System.setProperty("apollo.longPollingInitialDelayInMills", "0"); @@ -143,6 +145,34 @@ public void close() { } } + /** + * Installs the JUL-to-SLF4J bridge for MockWebServer logs on the currently active server. + * Callers must pair every call with {@link #releaseJulBridge()}. + * + *

A failed installation propagates and leaves neither the JUL logger nor the bridge's + * ownership count changed, so it can be retried and a later {@link #releaseJulBridge()} is a + * no-op. + */ + public void acquireJulBridge() { + if (!bridgeAcquired) { + JulSlf4jBridge.install(); + bridgeAcquired = true; + } + } + + /** + * Releases the JUL-to-SLF4J bridge acquired by {@link #acquireJulBridge()}. + * + *

A failed release keeps this instance owning the bridge, so calling this method again + * retries the teardown. + */ + public void releaseJulBridge() { + if (bridgeAcquired) { + JulSlf4jBridge.uninstall(); + bridgeAcquired = false; + } + } + public boolean isClosed() { return closed; } diff --git a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java new file mode 100644 index 00000000..548f4b8d --- /dev/null +++ b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java @@ -0,0 +1,189 @@ +/* + * Copyright 2026 Apollo Authors + * + * Licensed 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 com.ctrip.framework.apollo.mockserver; + +import java.util.concurrent.atomic.AtomicInteger; +import java.util.logging.Handler; +import java.util.logging.Logger; +import org.slf4j.LoggerFactory; + +/** + * Routes okhttp's MockWebServer logs (which go through java.util.logging directly) to + * slf4j/logback for the lifetime of active {@link ApolloTestingServer} instances. + * + *

Unlike {@code SLF4JBridgeHandler#install()}, this only touches the JUL logger used by + * MockWebServer, not the JUL root logger, so unrelated JUL handlers elsewhere in the JVM are + * never removed. It also skips installing when the SLF4J binding is slf4j-jdk14, since bridging + * JUL to an SLF4J binding that itself delegates back to JUL creates an infinite loop. Calls are + * reference-counted so concurrently running mock servers don't uninstall the bridge out from + * under each other. + * + *

The ownership count is only moved once the corresponding logger transition succeeded, so a + * failed {@link #install()} leaves the bridge reusable and a failed {@link #uninstall()} can be + * retried instead of driving the count out of sync with the JUL logger state. + * + *

Uses reflection to instantiate {@code SLF4JBridgeHandler} so the class can load even when + * {@code jul-to-slf4j} is not on the classpath. + */ +final class JulSlf4jBridge { + + private static final org.slf4j.Logger LOG = LoggerFactory.getLogger(JulSlf4jBridge.class); + private static final String MOCK_WEB_SERVER_LOGGER_NAME = "okhttp3.mockwebserver.MockWebServer"; + private static final String SLF4J_BRIDGE_HANDLER_CLASS = "org.slf4j.bridge.SLF4JBridgeHandler"; + private static final AtomicInteger ACTIVE = new AtomicInteger(0); + + private static Handler[] originalHandlers; + private static boolean originalUseParentHandlers; + private static boolean bridged; + private static Logger mockWebServerLogger; + private static Handler bridgeHandler; + + private JulSlf4jBridge() {} + + static synchronized void install() { + if (ACTIVE.get() <= 0) { + installForFirstOwner(); + } + // Only an owner whose install succeeded consumes a slot, so a failed install cannot make + // later servers skip their own installation. + ACTIVE.incrementAndGet(); + } + + private static void installForFirstOwner() { + if (!isBridgeHandlerAvailable()) { + LOG.warn("Skipping JUL-to-SLF4J bridge for MockWebServer logs because " + + "jul-to-slf4j is not on the classpath"); + return; + } + if (isJdk14Binding(LoggerFactory.getILoggerFactory().getClass().getName())) { + LOG.warn("Skipping JUL-to-SLF4J bridge for MockWebServer logs because the SLF4J binding " + + "is slf4j-jdk14; bridging it would create an infinite JUL<->SLF4J logging loop."); + return; + } + + Logger logger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + Handler[] handlers = logger.getHandlers(); + boolean useParentHandlers = logger.getUseParentHandlers(); + + Handler handler = null; + try { + handler = newBridgeHandler(); + for (Handler original : handlers) { + logger.removeHandler(original); + } + logger.addHandler(handler); + logger.setUseParentHandlers(false); + } catch (RuntimeException | Error e) { + // Leave no half-installed bridge behind, otherwise later servers would see a bridge + // count that no installed bridge corresponds to. + removeHandlerQuietly(logger, handler); + restoreHandlers(logger, handlers, useParentHandlers); + throw e; + } + + mockWebServerLogger = logger; + originalHandlers = handlers; + originalUseParentHandlers = useParentHandlers; + bridgeHandler = handler; + bridged = true; + } + + private static boolean isBridgeHandlerAvailable() { + try { + Class.forName(SLF4J_BRIDGE_HANDLER_CLASS); + return true; + } catch (ClassNotFoundException e) { + return false; + } + } + + private static Handler newBridgeHandler() { + try { + return (Handler) Class.forName(SLF4J_BRIDGE_HANDLER_CLASS).newInstance(); + } catch (ClassNotFoundException | InstantiationException | IllegalAccessException e) { + throw new IllegalStateException( + "SLF4JBridgeHandler was available during check but not during instantiation", e); + } + } + + static synchronized void uninstall() { + int active = ACTIVE.get(); + if (active <= 0) { + // Nothing is acquired, so releasing must not drive the count below zero. + return; + } + if (active > 1 || !bridged) { + ACTIVE.decrementAndGet(); + return; + } + // The last owner gives up its slot only once the JUL logger is restored, so a failed + // teardown stays retryable instead of leaving the count out of sync. + teardown(); + ACTIVE.decrementAndGet(); + } + + private static void teardown() { + mockWebServerLogger.removeHandler(bridgeHandler); + restoreHandlers(mockWebServerLogger, originalHandlers, originalUseParentHandlers); + originalHandlers = null; + originalUseParentHandlers = false; + mockWebServerLogger = null; + bridgeHandler = null; + bridged = false; + } + + /** Restores the previously removed handlers, without ever failing the caller. */ + private static void restoreHandlers(Logger logger, Handler[] handlers, + boolean useParentHandlers) { + try { + for (Handler handler : handlers) { + if (!containsHandler(logger.getHandlers(), handler)) { + logger.addHandler(handler); + } + } + logger.setUseParentHandlers(useParentHandlers); + } catch (RuntimeException | Error e) { + LOG.warn("Failed to restore the JUL handlers of {}", logger.getName(), e); + } + } + + private static void removeHandlerQuietly(Logger logger, Handler handler) { + if (handler == null) { + return; + } + try { + logger.removeHandler(handler); + } catch (RuntimeException | Error e) { + LOG.warn("Failed to remove the JUL bridge handler from {}", logger.getName(), e); + } + } + + private static boolean containsHandler(Handler[] handlers, Handler target) { + for (Handler handler : handlers) { + if (handler == target) { + return true; + } + } + return false; + } + + /** Package-visible for testing without depending on the actual runtime SLF4J binding. */ + static boolean isJdk14Binding(String iLoggerFactoryClassName) { + return "org.slf4j.impl.JDK14LoggerFactory".equals(iLoggerFactoryClassName) + || "org.slf4j.jul.JDK14LoggerFactory".equals(iLoggerFactoryClassName); + } +} diff --git a/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java b/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java new file mode 100644 index 00000000..614a476d --- /dev/null +++ b/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java @@ -0,0 +1,314 @@ +/* + * Copyright 2026 Apollo Authors + * + * Licensed 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 com.ctrip.framework.apollo.mockserver; + +import static org.junit.jupiter.api.Assertions.assertArrayEquals; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.junit.jupiter.api.Assumptions.assumeTrue; + +import java.lang.reflect.Field; +import java.security.Permission; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.logging.Handler; +import java.util.logging.Logger; +import java.util.logging.LoggingPermission; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.slf4j.bridge.SLF4JBridgeHandler; + +class JulSlf4jBridgeTest { + + private static final String MOCK_WEB_SERVER_LOGGER_NAME = "okhttp3.mockwebserver.MockWebServer"; + private static final boolean SECURITY_MANAGER_SUPPORTED = isSecurityManagerSupported(); + + @AfterEach + void releaseAnyBridgeOwnership() { + // The bridge is JVM global state; make every test start from an unowned bridge even when + // another test failed half way through. + for (int owned = activeCount(); owned > 0; owned--) { + JulSlf4jBridge.uninstall(); + } + } + + @Test + void isJdk14BindingDetectsKnownFactoryClassNames() { + assertTrue(JulSlf4jBridge.isJdk14Binding("org.slf4j.impl.JDK14LoggerFactory")); + assertTrue(JulSlf4jBridge.isJdk14Binding("org.slf4j.jul.JDK14LoggerFactory")); + assertFalse(JulSlf4jBridge.isJdk14Binding("ch.qos.logback.classic.LoggerContext")); + } + + @Test + void installOnlyTouchesMockWebServerLoggerNotRoot() { + Logger root = Logger.getLogger(""); + Handler[] rootHandlersBefore = root.getHandlers(); + + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + Handler[] mwsHandlersBefore = mockWebServerLogger.getHandlers(); + boolean useParentBefore = mockWebServerLogger.getUseParentHandlers(); + + JulSlf4jBridge.install(); + try { + assertArrayEquals(rootHandlersBefore, root.getHandlers(), + "installing the bridge must not touch the JUL root logger's handlers"); + assertTrue(hasBridgeHandler(mockWebServerLogger), + "MockWebServer's own logger should get the bridge handler"); + assertFalse(mockWebServerLogger.getUseParentHandlers()); + } finally { + JulSlf4jBridge.uninstall(); + } + + assertArrayEquals(rootHandlersBefore, root.getHandlers()); + assertArrayEquals(mwsHandlersBefore, mockWebServerLogger.getHandlers()); + assertEquals(useParentBefore, mockWebServerLogger.getUseParentHandlers()); + } + + @Test + void closingSameServerTwiceDoesNotDisruptAnotherActiveServer() throws Exception { + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + ApolloTestingServer serverA = new ApolloTestingServer(); + ApolloTestingServer serverB = new ApolloTestingServer(); + try { + serverA.start(); + serverA.acquireJulBridge(); + serverB.start(); + serverB.acquireJulBridge(); + assertTrue(hasBridgeHandler(mockWebServerLogger)); + + serverA.releaseJulBridge(); + serverA.releaseJulBridge(); + + assertTrue(hasBridgeHandler(mockWebServerLogger), + "bridge must remain installed while server B is still running"); + } finally { + serverA.releaseJulBridge(); + serverA.close(); + serverB.releaseJulBridge(); + serverB.close(); + } + + assertFalse(hasBridgeHandler(mockWebServerLogger)); + } + + @Test + void closingNeverStartedServerDoesNotDisruptActiveServer() throws Exception { + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + ApolloTestingServer active = new ApolloTestingServer(); + ApolloTestingServer neverStarted = new ApolloTestingServer(); + try { + active.start(); + active.acquireJulBridge(); + assertTrue(hasBridgeHandler(mockWebServerLogger)); + + neverStarted.releaseJulBridge(); + + assertTrue(hasBridgeHandler(mockWebServerLogger), + "releasing a bridge that was never acquired must not affect the active bridge"); + } finally { + active.releaseJulBridge(); + active.close(); + neverStarted.close(); + } + + assertFalse(hasBridgeHandler(mockWebServerLogger)); + } + + @Test + void failedAcquisitionKeepsTheBridgeAvailableForLaterServers() { + assumeTrue(SECURITY_MANAGER_SUPPORTED, + "denying java.util.logging control requires the security manager API"); + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + assertEquals(0, activeCount(), "the bridge must start out unowned"); + + ApolloTestingServer failing = new ApolloTestingServer(); + whileLoggingControlDenied( + () -> assertThrows(SecurityException.class, failing::acquireJulBridge)); + + assertEquals(0, activeCount(), "a failed acquisition must not consume the ownership"); + assertFalse(hasBridgeHandler(mockWebServerLogger), + "a failed acquisition must not leave a half-installed bridge behind"); + + ApolloTestingServer later = new ApolloTestingServer(); + later.acquireJulBridge(); + try { + assertEquals(1, activeCount()); + assertTrue(hasBridgeHandler(mockWebServerLogger), + "a later server must still be able to install the bridge"); + } finally { + later.releaseJulBridge(); + later.close(); + failing.close(); + } + + assertFalse(hasBridgeHandler(mockWebServerLogger)); + } + + @Test + void failedReleaseKeepsTheOwnershipSoThatItCanBeRetried() { + assumeTrue(SECURITY_MANAGER_SUPPORTED, + "denying java.util.logging control requires the security manager API"); + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + assertEquals(0, activeCount(), "the bridge must start out unowned"); + + ApolloTestingServer server = new ApolloTestingServer(); + server.acquireJulBridge(); + try { + assertTrue(hasBridgeHandler(mockWebServerLogger)); + + whileLoggingControlDenied( + () -> assertThrows(SecurityException.class, server::releaseJulBridge)); + + assertEquals(1, activeCount(), "a failed release must keep the ownership for a retry"); + assertTrue(hasBridgeHandler(mockWebServerLogger), + "a failed release must leave the bridge installed"); + + server.releaseJulBridge(); + assertEquals(0, activeCount()); + assertFalse(hasBridgeHandler(mockWebServerLogger)); + + server.releaseJulBridge(); + assertEquals(0, activeCount(), "releasing more often than acquiring must not go negative"); + } finally { + server.releaseJulBridge(); + server.close(); + } + } + + @Test + void bridgeRetainsLoggerUntilMockWebServerInitializes() throws Exception { + ApolloTestingServer server = new ApolloTestingServer(); + try { + server.start(); + server.acquireJulBridge(); + + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + assertSame(mockWebServerLogger, retainedMockWebServerLogger(), + "the bridge must retain the logger MockWebServer logs to, so that GC cannot " + + "silently detach its bridge handler"); + assertTrue(hasBridgeHandler(mockWebServerLogger), + "the MockWebServer logger must keep its bridge handler for the bridge's lifetime"); + } finally { + server.releaseJulBridge(); + server.close(); + } + + assertNullRetainedLogger(); + } + + @Test + void startupFailureDoesNotInstallBridge() throws Exception { + Logger mockWebServerLogger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + ApolloTestingServer server = new ApolloTestingServer(); + + Field locatorField = ApolloTestingServer.class.getDeclaredField("CONFIG_SERVICE_LOCATOR"); + locatorField.setAccessible(true); + Object originalLocator = locatorField.get(null); + locatorField.set(null, null); + try { + assertThrows(IllegalStateException.class, server::start, "start() must surface failures"); + assertFalse(hasBridgeHandler(mockWebServerLogger), + "a failed start() must not install the JUL bridge"); + } finally { + locatorField.set(null, originalLocator); + server.close(); + } + } + + private static boolean hasBridgeHandler(Logger logger) { + for (Handler handler : logger.getHandlers()) { + if (handler instanceof SLF4JBridgeHandler) { + return true; + } + } + return false; + } + + private static void assertNullRetainedLogger() { + assertNull(retainedMockWebServerLogger(), + "the bridge must release the retained logger on teardown"); + } + + private static int activeCount() { + try { + Field active = JulSlf4jBridge.class.getDeclaredField("ACTIVE"); + active.setAccessible(true); + return ((AtomicInteger) active.get(null)).get(); + } catch (ReflectiveOperationException e) { + throw new IllegalStateException(e); + } + } + + private static Logger retainedMockWebServerLogger() { + try { + Field field = JulSlf4jBridge.class.getDeclaredField("mockWebServerLogger"); + field.setAccessible(true); + return (Logger) field.get(null); + } catch (ReflectiveOperationException e) { + throw new IllegalStateException(e); + } + } + + /** + * Runs {@code action} while {@code java.util.logging} control checks are denied, which is how a + * JVM without permission to reconfigure JUL behaves. + */ + private static void whileLoggingControlDenied(Runnable action) { + DenyLoggingControlSecurityManager securityManager = new DenyLoggingControlSecurityManager(); + System.setSecurityManager(securityManager); + try { + securityManager.denyLoggingControl = true; + action.run(); + } finally { + securityManager.denyLoggingControl = false; + System.setSecurityManager(null); + } + } + + private static boolean isSecurityManagerSupported() { + try { + System.setSecurityManager(new DenyLoggingControlSecurityManager()); + System.setSecurityManager(null); + return true; + } catch (Throwable t) { + return false; + } + } + + /** Allows everything but {@code LoggingPermission("control")}, so JUL reconfiguration fails. */ + private static final class DenyLoggingControlSecurityManager extends SecurityManager { + + private boolean denyLoggingControl; + + @Override + public void checkPermission(Permission permission) { + // java.util.logging checks LoggingPermission("control") before every reconfiguration. + if (denyLoggingControl && permission instanceof LoggingPermission + && "control".equals(permission.getName())) { + throw new SecurityException("denied " + permission); + } + } + + @Override + public void checkPermission(Permission permission, Object context) { + checkPermission(permission); + } + } +} From 28dd03a20b847006b920830755904a30657155d2 Mon Sep 17 00:00:00 2001 From: "shalk(xiao kun)" Date: Tue, 27 Oct 2026 19:44:57 +0800 Subject: [PATCH 2/2] fix(mockserver): retain JUL recovery state after partial failures Retain the original JUL baseline until restoration succeeds so failed rollback and final release can be retried without losing handlers or ownership. Cover each JUL mutation stage and document exception-safe opt-in cleanup. Assisted-by: Claude Opus 5 --- apollo-mockserver/README.md | 53 +++ .../mockserver/ApolloTestingServer.java | 10 +- .../apollo/mockserver/JulSlf4jBridge.java | 78 ++-- .../apollo/mockserver/JulSlf4jBridgeTest.java | 341 +++++++++++++++++- 4 files changed, 436 insertions(+), 46 deletions(-) create mode 100644 apollo-mockserver/README.md diff --git a/apollo-mockserver/README.md b/apollo-mockserver/README.md new file mode 100644 index 00000000..a79890ed --- /dev/null +++ b/apollo-mockserver/README.md @@ -0,0 +1,53 @@ +# Apollo Mock Server + +## Routing MockWebServer logs to SLF4J + +MockWebServer uses `java.util.logging` (JUL). The bridge is opt-in: `start()` and +`close()` do not install or release it. Add `jul-to-slf4j` to your test classpath, +since the dependency in `apollo-mockserver` is optional: + +```xml + + org.slf4j + jul-to-slf4j + 1.7.21 + test + +``` + +Explicitly acquire and release the bridge, ensuring the server closes even if +acquisition or release throws: + +```java +ApolloTestingServer server = new ApolloTestingServer(); +try { + server.start(); + server.acquireJulBridge(); + // ... +} finally { + try { + server.releaseJulBridge(); + } finally { + server.close(); + } +} +``` + +The bridge only reconfigures the `okhttp3.mockwebserver.MockWebServer` logger, +not the JUL root logger. Each server can own at most one acquisition; the bridge +is shared until the last owner releases it. Without `jul-to-slf4j`, or when the +SLF4J backend is `slf4j-jdk14`, acquisition logs a warning and leaves JUL logging +unchanged. + +A failed acquisition creates no successful owner. It restores the original JUL +state immediately if possible. If rollback also fails, its exception is attached +to the acquisition exception as a suppressed exception, and the original state +is retained. A later acquisition must complete that recovery before installing a +new bridge; it throws if recovery is still blocked. + +A failed final release throws and retains the last owner's acquisition and the +original JUL state for a retry. New owners cannot acquire during incomplete +teardown; the existing owner must retry `releaseJulBridge()` after the cause of +the failure is removed. The nested `finally` above guarantees server cleanup, +but handling or retrying a reported bridge-release failure remains the caller's +responsibility. Calling `close()` does not release bridge ownership. diff --git a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java index 4aae4d07..06fe8b25 100644 --- a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java +++ b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/ApolloTestingServer.java @@ -149,9 +149,13 @@ public void close() { * Installs the JUL-to-SLF4J bridge for MockWebServer logs on the currently active server. * Callers must pair every call with {@link #releaseJulBridge()}. * - *

A failed installation propagates and leaves neither the JUL logger nor the bridge's - * ownership count changed, so it can be retried and a later {@link #releaseJulBridge()} is a - * no-op. + *

A failed installation propagates without acquiring ownership and attempts to restore the + * original JUL state. If rollback also fails, the cleanup exception is suppressed on the + * installation exception and recovery state is retained for a later acquisition to retry. + * Releasing an instance whose acquisition failed is a no-op. + * + *

If another owner's final release is incomplete, acquisition throws until that owner + * successfully retries {@link #releaseJulBridge()}. */ public void acquireJulBridge() { if (!bridgeAcquired) { diff --git a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java index 548f4b8d..9154e60a 100644 --- a/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java +++ b/apollo-mockserver/src/main/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridge.java @@ -32,9 +32,9 @@ * reference-counted so concurrently running mock servers don't uninstall the bridge out from * under each other. * - *

The ownership count is only moved once the corresponding logger transition succeeded, so a - * failed {@link #install()} leaves the bridge reusable and a failed {@link #uninstall()} can be - * retried instead of driving the count out of sync with the JUL logger state. + *

The ownership count is only moved once the corresponding logger transition succeeded. + * Failed restoration retains the original JUL state for retry: a later installation recovers + * ownerless rollback, and a failed final release must be retried by its existing owner. * *

Uses reflection to instantiate {@code SLF4JBridgeHandler} so the class can load even when * {@code jul-to-slf4j} is not on the classpath. @@ -49,13 +49,23 @@ final class JulSlf4jBridge { private static Handler[] originalHandlers; private static boolean originalUseParentHandlers; private static boolean bridged; + private static boolean recoveryPending; private static Logger mockWebServerLogger; private static Handler bridgeHandler; private JulSlf4jBridge() {} static synchronized void install() { - if (ACTIVE.get() <= 0) { + if (recoveryPending) { + if (ACTIVE.get() > 0) { + throw new IllegalStateException( + "JUL bridge teardown is incomplete; the last owner must retry releaseJulBridge()"); + } + // A failed acquisition has no owner to retry release. Recover its original baseline + // before taking a new snapshot, so a leftover bridge is never treated as an original. + teardown(); + } + if (ACTIVE.get() == 0) { installForFirstOwner(); } // Only an owner whose install succeeded consumes a slot, so a failed install cannot make @@ -76,30 +86,32 @@ private static void installForFirstOwner() { } Logger logger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); - Handler[] handlers = logger.getHandlers(); - boolean useParentHandlers = logger.getUseParentHandlers(); + Handler handler = newBridgeHandler(); + mockWebServerLogger = logger; + originalHandlers = logger.getHandlers(); + originalUseParentHandlers = logger.getUseParentHandlers(); + bridgeHandler = handler; + recoveryPending = true; - Handler handler = null; try { - handler = newBridgeHandler(); - for (Handler original : handlers) { + for (Handler original : originalHandlers) { logger.removeHandler(original); } logger.addHandler(handler); logger.setUseParentHandlers(false); } catch (RuntimeException | Error e) { - // Leave no half-installed bridge behind, otherwise later servers would see a bridge - // count that no installed bridge corresponds to. - removeHandlerQuietly(logger, handler); - restoreHandlers(logger, handlers, useParentHandlers); + try { + teardown(); + } catch (RuntimeException | Error cleanupFailure) { + if (cleanupFailure != e) { + e.addSuppressed(cleanupFailure); + } + } throw e; } - mockWebServerLogger = logger; - originalHandlers = handlers; - originalUseParentHandlers = useParentHandlers; - bridgeHandler = handler; bridged = true; + recoveryPending = false; } private static boolean isBridgeHandlerAvailable() { @@ -137,38 +149,30 @@ static synchronized void uninstall() { } private static void teardown() { - mockWebServerLogger.removeHandler(bridgeHandler); + recoveryPending = true; + if (containsHandler(mockWebServerLogger.getHandlers(), bridgeHandler)) { + mockWebServerLogger.removeHandler(bridgeHandler); + } restoreHandlers(mockWebServerLogger, originalHandlers, originalUseParentHandlers); + // Keep the snapshot, logger and last ownership until every restoration operation succeeds. originalHandlers = null; originalUseParentHandlers = false; mockWebServerLogger = null; bridgeHandler = null; bridged = false; + recoveryPending = false; } - /** Restores the previously removed handlers, without ever failing the caller. */ + /** Restores only missing original handlers, preserving handlers added by other components. */ private static void restoreHandlers(Logger logger, Handler[] handlers, boolean useParentHandlers) { - try { - for (Handler handler : handlers) { - if (!containsHandler(logger.getHandlers(), handler)) { - logger.addHandler(handler); - } + for (Handler handler : handlers) { + if (!containsHandler(logger.getHandlers(), handler)) { + logger.addHandler(handler); } - logger.setUseParentHandlers(useParentHandlers); - } catch (RuntimeException | Error e) { - LOG.warn("Failed to restore the JUL handlers of {}", logger.getName(), e); - } - } - - private static void removeHandlerQuietly(Logger logger, Handler handler) { - if (handler == null) { - return; } - try { - logger.removeHandler(handler); - } catch (RuntimeException | Error e) { - LOG.warn("Failed to remove the JUL bridge handler from {}", logger.getName(), e); + if (logger.getUseParentHandlers() != useParentHandlers) { + logger.setUseParentHandlers(useParentHandlers); } } diff --git a/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java b/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java index 614a476d..e7b455cc 100644 --- a/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java +++ b/apollo-mockserver/src/test/java/com/ctrip/framework/apollo/mockserver/JulSlf4jBridgeTest.java @@ -29,10 +29,14 @@ import java.security.Permission; import java.util.concurrent.atomic.AtomicInteger; import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; import java.util.logging.Logger; import java.util.logging.LoggingPermission; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.CsvSource; import org.slf4j.bridge.SLF4JBridgeHandler; class JulSlf4jBridgeTest { @@ -192,6 +196,157 @@ void failedReleaseKeepsTheOwnershipSoThatItCanBeRetried() { } } + @ParameterizedTest + @CsvSource({"removeHandler, 1", "removeHandler, 2", "addHandler, 1", "setUseParentHandlers, 1"}) + void failedAcquisitionRestoresEveryMutationStage(String method, int occurrence) { + assumeTrue(SECURITY_MANAGER_SUPPORTED); + try (LoggerState state = new LoggerState()) { + ApolloTestingServer failing = new ApolloTestingServer(); + whileLoggingControlFails(() -> { + SecurityException failure = + assertThrows(SecurityException.class, failing::acquireJulBridge); + assertTrue(failure.getMessage().contains(method)); + assertEquals(0, failure.getSuppressed().length, "immediate rollback should succeed"); + }, new LoggingFailure(method, occurrence, false)); + + assertEquals(0, activeCount()); + assertOwnership(failing, false); + failing.releaseJulBridge(); + assertRestored(state); + assertFreshAcquisitionWorks(state); + } + } + + @ParameterizedTest + @CsvSource({"removeHandler, 1", "addHandler, 1", "addHandler, 2", "setUseParentHandlers, 1"}) + void failedFinalReleaseRetainsRecoveryAtEveryMutationStage(String method, int occurrence) { + assumeTrue(SECURITY_MANAGER_SUPPORTED); + try (LoggerState state = new LoggerState()) { + ApolloTestingServer owner = new ApolloTestingServer(); + ApolloTestingServer later = new ApolloTestingServer(); + owner.acquireJulBridge(); + + whileLoggingControlFails(() -> { + assertThrows(SecurityException.class, owner::releaseJulBridge); + assertEquals(1, activeCount()); + assertOwnership(owner, true); + assertRecoveryState(state); + if ("removeHandler".equals(method)) { + assertTrue(hasBridgeHandler(state.logger)); + } else { + assertFalse(hasBridgeHandler(state.logger)); + if ("addHandler".equals(method)) { + assertEquals(occurrence - 1, state.logger.getHandlers().length, + "earlier handler restoration must succeed before the targeted failure"); + } + } + assertFalse(state.logger.getUseParentHandlers()); + + assertThrows(SecurityException.class, owner::releaseJulBridge, + "retry must report restoration that is still blocked"); + assertThrows(IllegalStateException.class, later::acquireJulBridge, + "a new owner must not acknowledge a partially torn-down bridge"); + assertOwnership(later, false); + assertEquals(1, activeCount()); + assertRecoveryState(state); + }, new LoggingFailure(method, occurrence, true)); + + owner.releaseJulBridge(); + assertOwnership(owner, false); + assertRestored(state); + owner.releaseJulBridge(); + assertEquals(0, activeCount(), "repeated release must remain a no-op"); + assertFreshAcquisitionWorks(state); + } + } + + @ParameterizedTest + @CsvSource({"setUseParentHandlers, 1, removeHandler, 3", "setUseParentHandlers, 1, addHandler, 2", + "removeHandler, 2, addHandler, 1"}) + void failedAcquisitionRollbackRetainsBaselineForLaterRecovery(String acquisitionMethod, + int acquisitionOccurrence, String rollbackMethod, int rollbackOccurrence) { + assumeTrue(SECURITY_MANAGER_SUPPORTED); + try (LoggerState state = new LoggerState()) { + ApolloTestingServer failing = new ApolloTestingServer(); + whileLoggingControlFails(() -> { + SecurityException failure = + assertThrows(SecurityException.class, failing::acquireJulBridge); + assertTrue(failure.getMessage().contains(acquisitionMethod)); + assertEquals(1, failure.getSuppressed().length, + "rollback failure must be observable without hiding the acquisition failure"); + assertTrue(failure.getSuppressed()[0].getMessage().contains(rollbackMethod)); + assertEquals(0, activeCount()); + assertOwnership(failing, false); + assertRecoveryState(state); + }, new LoggingFailure(acquisitionMethod, acquisitionOccurrence, false), + new LoggingFailure(rollbackMethod, rollbackOccurrence, false)); + + failing.releaseJulBridge(); + assertEquals(0, activeCount(), "failed acquisition creates no owner to release"); + assertRecoveryState(state); + assertFreshAcquisitionWorks(state); + } + } + + @Test + void acquisitionMustRecoverPendingRollbackBeforeCreatingAnOwner() { + assumeTrue(SECURITY_MANAGER_SUPPORTED); + try (LoggerState state = new LoggerState()) { + ApolloTestingServer failing = new ApolloTestingServer(); + ApolloTestingServer later = new ApolloTestingServer(); + whileLoggingControlFails(() -> { + SecurityException failure = + assertThrows(SecurityException.class, failing::acquireJulBridge); + assertEquals(1, failure.getSuppressed().length); + assertTrue(hasBridgeHandler(state.logger), "rollback removal is deliberately blocked"); + + assertThrows(SecurityException.class, later::acquireJulBridge, + "pending rollback must be recovered before a new installation"); + assertOwnership(failing, false); + assertOwnership(later, false); + assertEquals(0, activeCount()); + assertRecoveryState(state); + }, new LoggingFailure("setUseParentHandlers", 1, false), + new LoggingFailure("removeHandler", 3, true)); + + later.acquireJulBridge(); + assertOwnership(later, true); + assertEquals(1, activeCount()); + assertEquals(1, state.logger.getHandlers().length, + "the leftover bridge must not be adopted as an original handler"); + assertTrue(hasBridgeHandler(state.logger)); + later.releaseJulBridge(); + later.releaseJulBridge(); + assertRestored(state); + assertFreshAcquisitionWorks(state); + } + } + + @Test + void finalReleasePreservesAddedHandlersWithoutDuplicatingOriginals() { + try (LoggerState state = new LoggerState()) { + ApolloTestingServer server = new ApolloTestingServer(); + server.acquireJulBridge(); + CaptureHandler added = new CaptureHandler(); + state.logger.addHandler(added); + state.logger.addHandler(state.first); + + server.releaseJulBridge(); + assertEquals(0, activeCount()); + Handler[] restored = state.logger.getHandlers(); + assertEquals(3, restored.length); + assertSame(added, restored[0]); + assertSame(state.first, restored[1]); + assertSame(state.second, restored[2]); + assertTrue(state.logger.getUseParentHandlers()); + assertNullRetainedLogger(); + state.logger.info("record after restoring handlers"); + assertEquals(1, state.first.records); + assertEquals(1, state.second.records); + assertEquals(1, added.records); + } + } + @Test void bridgeRetainsLoggerUntilMockWebServerInitializes() throws Exception { ApolloTestingServer server = new ApolloTestingServer(); @@ -232,6 +387,65 @@ void startupFailureDoesNotInstallBridge() throws Exception { } } + private static void assertRecoveryState(LoggerState state) { + assertSame(state.logger, retainedMockWebServerLogger()); + assertArrayEquals(new Handler[] {state.first, state.second}, + (Handler[]) retainedField("originalHandlers")); + assertEquals(true, retainedField("originalUseParentHandlers")); + } + + private static void assertOwnership(ApolloTestingServer server, boolean owned) { + try { + Field field = ApolloTestingServer.class.getDeclaredField("bridgeAcquired"); + field.setAccessible(true); + assertEquals(owned, field.getBoolean(server)); + } catch (ReflectiveOperationException e) { + throw new IllegalStateException(e); + } + } + + private static void assertRestored(LoggerState state) { + assertEquals(0, activeCount()); + Handler[] handlers = state.logger.getHandlers(); + assertEquals(2, handlers.length); + assertTrue(handlers[0] == state.first || handlers[1] == state.first); + assertTrue(handlers[0] == state.second || handlers[1] == state.second); + assertTrue(state.logger.getUseParentHandlers()); + assertFalse(hasBridgeHandler(state.logger)); + assertNullRetainedLogger(); + assertNull(retainedField("originalHandlers")); + assertNull(retainedField("bridgeHandler")); + + int firstRecords = state.first.records; + int secondRecords = state.second.records; + state.logger.info("record after recovering JUL state"); + assertEquals(firstRecords + 1, state.first.records); + assertEquals(secondRecords + 1, state.second.records); + } + + private static void assertFreshAcquisitionWorks(LoggerState state) { + ApolloTestingServer fresh = new ApolloTestingServer(); + fresh.acquireJulBridge(); + fresh.acquireJulBridge(); + assertEquals(1, activeCount()); + assertEquals(1, state.logger.getHandlers().length); + assertTrue(hasBridgeHandler(state.logger)); + fresh.releaseJulBridge(); + fresh.releaseJulBridge(); + assertOwnership(fresh, false); + assertRestored(state); + } + + private static Object retainedField(String name) { + try { + Field field = JulSlf4jBridge.class.getDeclaredField(name); + field.setAccessible(true); + return field.get(null); + } catch (ReflectiveOperationException e) { + throw new IllegalStateException(e); + } + } + private static boolean hasBridgeHandler(Logger logger) { for (Handler handler : logger.getHandlers()) { if (handler instanceof SLF4JBridgeHandler) { @@ -272,37 +486,152 @@ private static Logger retainedMockWebServerLogger() { */ private static void whileLoggingControlDenied(Runnable action) { DenyLoggingControlSecurityManager securityManager = new DenyLoggingControlSecurityManager(); + SecurityManager original = System.getSecurityManager(); + System.setSecurityManager(securityManager); + try { + securityManager.denyLoggingControl = true; + action.run(); + } finally { + securityManager.denyLoggingControl = false; + System.setSecurityManager(original); + } + } + + private static void whileLoggingControlFails(Runnable action, LoggingFailure... failures) { + DenyLoggingControlSecurityManager securityManager = + new DenyLoggingControlSecurityManager(failures); + SecurityManager original = System.getSecurityManager(); System.setSecurityManager(securityManager); try { securityManager.denyLoggingControl = true; action.run(); } finally { securityManager.denyLoggingControl = false; - System.setSecurityManager(null); + System.setSecurityManager(original); } } private static boolean isSecurityManagerSupported() { + SecurityManager original = System.getSecurityManager(); try { System.setSecurityManager(new DenyLoggingControlSecurityManager()); - System.setSecurityManager(null); + System.setSecurityManager(original); return true; - } catch (Throwable t) { + } catch (UnsupportedOperationException | SecurityException e) { return false; } } - /** Allows everything but {@code LoggingPermission("control")}, so JUL reconfiguration fails. */ + private static final class LoggerState implements AutoCloseable { + + private final Logger logger = Logger.getLogger(MOCK_WEB_SERVER_LOGGER_NAME); + private final Handler[] handlers = logger.getHandlers(); + private final boolean useParentHandlers = logger.getUseParentHandlers(); + private final Level level = logger.getLevel(); + private final CaptureHandler first = new CaptureHandler(); + private final CaptureHandler second = new CaptureHandler(); + + private LoggerState() { + for (Handler handler : handlers) { + logger.removeHandler(handler); + } + logger.addHandler(first); + logger.addHandler(second); + logger.setUseParentHandlers(true); + logger.setLevel(Level.ALL); + } + + @Override + public void close() { + try { + // An acquisition can leave pending rollback without a successful owner. Recover it + // through the public transition rather than clearing the bridge's private state. + if (activeCount() == 0 && retainedMockWebServerLogger() != null) { + JulSlf4jBridge.install(); + } + while (activeCount() > 0) { + JulSlf4jBridge.uninstall(); + } + } finally { + for (Handler handler : logger.getHandlers()) { + logger.removeHandler(handler); + } + for (Handler handler : handlers) { + logger.addHandler(handler); + } + logger.setUseParentHandlers(useParentHandlers); + logger.setLevel(level); + } + } + } + + private static final class CaptureHandler extends Handler { + + private int records; + + @Override + public void publish(LogRecord record) { + records++; + } + + @Override + public void flush() {} + + @Override + public void close() {} + } + + private static final class LoggingFailure { + + private final String method; + private final int occurrence; + private final boolean persistent; + private int calls; + + private LoggingFailure(String method, int occurrence, boolean persistent) { + this.method = method; + this.occurrence = occurrence; + this.persistent = persistent; + } + + private void check(String mutation) { + if (method.equals(mutation)) { + calls++; + if (calls == occurrence || persistent && calls > occurrence) { + throw new SecurityException("denied Logger." + method + " at call " + calls); + } + } + } + } + + /** Can deny all logging control, or only a chosen occurrence of a JUL mutation. */ private static final class DenyLoggingControlSecurityManager extends SecurityManager { + private final LoggingFailure[] failures; private boolean denyLoggingControl; + private DenyLoggingControlSecurityManager(LoggingFailure... failures) { + this.failures = failures; + } + @Override public void checkPermission(Permission permission) { - // java.util.logging checks LoggingPermission("control") before every reconfiguration. if (denyLoggingControl && permission instanceof LoggingPermission && "control".equals(permission.getName())) { - throw new SecurityException("denied " + permission); + if (failures.length == 0) { + throw new SecurityException("denied " + permission); + } + for (StackTraceElement frame : Thread.currentThread().getStackTrace()) { + if (Logger.class.getName().equals(frame.getClassName()) + && ("removeHandler".equals(frame.getMethodName()) + || "addHandler".equals(frame.getMethodName()) + || "setUseParentHandlers".equals(frame.getMethodName()))) { + for (LoggingFailure failure : failures) { + failure.check(frame.getMethodName()); + } + return; + } + } } }