Skip to content

Commit 89878bd

Browse files
vietjvietj
committed
Improve the resiliency of Vert.x Logger.
Motivation: Vert.x should improve it's logger resiliency when handling faulty loggers, otherwise special care needs to be taken when logging happens in order to avoid breaking invariants, for instance TaskQueue log taks failures and assumes that the logging will not fail. Changes: Vert.x should redirect logger failures to a special global handler (to avoid ignoring them) and isolate the caller of such issues as part of the Logger contract.
1 parent 4a756df commit 89878bd

5 files changed

Lines changed: 331 additions & 19 deletions

File tree

‎vertx-core-logging/src/main/java/io/vertx/core/internal/logging/LoggerAdapter.java‎

Lines changed: 105 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -13,91 +13,180 @@
1313

1414
import io.vertx.core.spi.logging.LogDelegate;
1515

16+
import java.util.Objects;
17+
import java.util.function.Consumer;
18+
1619
/**
1720
* @author Thomas Segismont
1821
*/
1922
public final class LoggerAdapter implements Logger {
2023

24+
private static volatile Consumer<Throwable> loggerFailureHandler;
25+
26+
/**
27+
* Set a JVM wide handler that gets reported exception thrown by actual logger implementations.
28+
*
29+
* @param handler the handler getting reported failures
30+
*/
31+
public static void setLoggerFailureHandler(Consumer<Throwable> handler) {
32+
loggerFailureHandler = handler;
33+
}
34+
2135
private final LogDelegate adapted;
2236

2337
// Visible for testing
2438
public LoggerAdapter(LogDelegate adapted) {
25-
this.adapted = adapted;
39+
this.adapted = Objects.requireNonNull(adapted);
40+
}
41+
42+
private static void reportLoggerFailure(Throwable t) {
43+
Consumer<Throwable> handler = loggerFailureHandler;
44+
if (handler != null) {
45+
try {
46+
handler.accept(t);
47+
} catch (Throwable ignore) {
48+
}
49+
}
2650
}
2751

2852
@Override
2953
public String implementation() {
30-
return adapted.implementation();
54+
try {
55+
return adapted.implementation();
56+
} catch (Exception e) {
57+
reportLoggerFailure(e);
58+
return "Unknown";
59+
}
3160
}
3261

3362
@Override
3463
public boolean isTraceEnabled() {
35-
return adapted.isTraceEnabled();
64+
try {
65+
return adapted.isTraceEnabled();
66+
} catch (Exception e) {
67+
reportLoggerFailure(e);
68+
return false;
69+
}
3670
}
3771

3872
@Override
3973
public void trace(Object message) {
40-
adapted.trace(message);
74+
try {
75+
adapted.trace(message);
76+
} catch (Exception e) {
77+
reportLoggerFailure(e);
78+
}
4179
}
4280

4381
@Override
4482
public void trace(Object message, Throwable t) {
45-
adapted.trace(message, t);
83+
try {
84+
adapted.trace(message, t);
85+
} catch (Exception e) {
86+
reportLoggerFailure(e);
87+
}
4688
}
4789

4890
@Override
4991
public boolean isDebugEnabled() {
50-
return adapted.isDebugEnabled();
92+
try {
93+
return adapted.isDebugEnabled();
94+
} catch (Exception e) {
95+
reportLoggerFailure(e);
96+
return false;
97+
}
5198
}
5299

53100
@Override
54101
public void debug(Object message) {
55-
adapted.debug(message);
102+
try {
103+
adapted.debug(message);
104+
} catch (Exception e) {
105+
reportLoggerFailure(e);
106+
}
56107
}
57108

58109
@Override
59110
public void debug(Object message, Throwable t) {
60-
adapted.debug(message, t);
111+
try {
112+
adapted.debug(message, t);
113+
} catch (Exception e) {
114+
reportLoggerFailure(e);
115+
}
61116
}
62117

63118
@Override
64119
public boolean isInfoEnabled() {
65-
return adapted.isInfoEnabled();
120+
try {
121+
return adapted.isInfoEnabled();
122+
} catch (Exception e) {
123+
reportLoggerFailure(e);
124+
return false;
125+
}
66126
}
67127

68128
@Override
69129
public void info(Object message) {
70-
adapted.info(message);
130+
try {
131+
adapted.info(message);
132+
} catch (Exception e) {
133+
reportLoggerFailure(e);
134+
}
71135
}
72136

73137
@Override
74138
public void info(Object message, Throwable t) {
75-
adapted.info(message, t);
139+
try {
140+
adapted.info(message, t);
141+
} catch (Exception e) {
142+
reportLoggerFailure(e);
143+
}
76144
}
77145

78146
@Override
79147
public boolean isWarnEnabled() {
80-
return adapted.isWarnEnabled();
148+
try {
149+
return adapted.isWarnEnabled();
150+
} catch (Exception e) {
151+
reportLoggerFailure(e);
152+
return false;
153+
}
81154
}
82155

83156
@Override
84157
public void warn(Object message) {
85-
adapted.warn(message);
158+
try {
159+
adapted.warn(message);
160+
} catch (Exception e) {
161+
reportLoggerFailure(e);
162+
}
86163
}
87164

88165
@Override
89166
public void warn(Object message, Throwable t) {
90-
adapted.warn(message, t);
167+
try {
168+
adapted.warn(message, t);
169+
} catch (Exception e) {
170+
reportLoggerFailure(e);
171+
}
91172
}
92173

93174
@Override
94175
public void error(Object message) {
95-
adapted.error(message);
176+
try {
177+
adapted.error(message);
178+
} catch (Exception e) {
179+
reportLoggerFailure(e);
180+
}
96181
}
97182

98183
@Override
99184
public void error(Object message, Throwable t) {
100-
adapted.error(message, t);
185+
try {
186+
adapted.error(message, t);
187+
} catch (Exception e) {
188+
reportLoggerFailure(e);
189+
}
101190
}
102191

103192
public LogDelegate unwrap() {

‎vertx-core-logging/src/main/java/module-info.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,5 +16,6 @@
1616
// Internal API
1717

1818
exports io.vertx.core.internal.logging;
19+
exports io.vertx.core.spi.logging;
1920

2021
}

‎vertx-core-logging/src/test/java/io/vertx/it/ResilienceTest.java‎

Lines changed: 135 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,135 @@
1+
package io.vertx.it;
2+
3+
import io.vertx.core.internal.logging.Logger;
4+
import io.vertx.core.internal.logging.LoggerAdapter;
5+
import io.vertx.core.spi.logging.LogDelegate;
6+
import org.assertj.core.api.Assertions;
7+
import org.junit.Before;
8+
import org.junit.Test;
9+
10+
import java.util.ArrayList;
11+
import java.util.HashMap;
12+
import java.util.List;
13+
import java.util.Map;
14+
import java.util.concurrent.atomic.AtomicInteger;
15+
16+
import static org.junit.Assert.assertEquals;
17+
import static org.junit.Assert.assertNotNull;
18+
19+
public class ResilienceTest {
20+
21+
private static final RuntimeException ERR = new RuntimeException();
22+
23+
final Map<String, AtomicInteger> loggerUsage = new HashMap<>();
24+
LogDelegate logDelegate = new LogDelegate() {
25+
private <T> T fail() {
26+
StackTraceElement[] trace = Thread.currentThread().getStackTrace();
27+
StackTraceElement elt = trace[2];
28+
AtomicInteger cnt = loggerUsage.computeIfAbsent(elt.getMethodName(), curr -> new AtomicInteger());
29+
cnt.incrementAndGet();
30+
throw ERR;
31+
}
32+
@Override
33+
public String implementation() {
34+
return fail();
35+
}
36+
@Override
37+
public boolean isWarnEnabled() {
38+
return fail();
39+
}
40+
@Override
41+
public boolean isInfoEnabled() {
42+
return fail();
43+
}
44+
@Override
45+
public boolean isDebugEnabled() {
46+
return fail();
47+
}
48+
@Override
49+
public boolean isTraceEnabled() {
50+
return fail();
51+
}
52+
@Override
53+
public void error(Object message) {
54+
fail();
55+
}
56+
@Override
57+
public void error(Object message, Throwable t) {
58+
fail();
59+
}
60+
@Override
61+
public void warn(Object message) {
62+
fail();
63+
}
64+
@Override
65+
public void warn(Object message, Throwable t) {
66+
fail();
67+
}
68+
@Override
69+
public void info(Object message) {
70+
fail();
71+
}
72+
@Override
73+
public void info(Object message, Throwable t) {
74+
fail();
75+
}
76+
@Override
77+
public void debug(Object message) {
78+
fail();
79+
}
80+
@Override
81+
public void debug(Object message, Throwable t) {
82+
fail();
83+
}
84+
@Override
85+
public void trace(Object message) {
86+
fail();
87+
}
88+
@Override
89+
public void trace(Object message, Throwable t) {
90+
fail();
91+
}
92+
};
93+
94+
@Before
95+
public void before() {
96+
loggerUsage.clear();
97+
}
98+
99+
@Test
100+
public void testCatchAndReportFailures() {
101+
Logger logger = new LoggerAdapter(logDelegate);
102+
List<Throwable> uncaughtReports = new ArrayList<>();
103+
LoggerAdapter.setLoggerFailureHandler(uncaughtReports::add);
104+
try {
105+
logger.isDebugEnabled();
106+
assertEquals(1, loggerUsage.size());
107+
AtomicInteger c = loggerUsage.get("isDebugEnabled");
108+
assertNotNull(c);
109+
assertEquals(1, c.get());
110+
assertEquals(List.of(ERR), uncaughtReports);
111+
} finally {
112+
LoggerAdapter.setLoggerFailureHandler(null);
113+
}
114+
}
115+
116+
@Test
117+
public void testUncaughtHandlerFailure() {
118+
AtomicInteger uncaughtCount = new AtomicInteger();
119+
Logger logger = new LoggerAdapter(logDelegate);
120+
LoggerAdapter.setLoggerFailureHandler(err -> {
121+
uncaughtCount.incrementAndGet();
122+
throw new AssertionError();
123+
});
124+
try {
125+
logger.isDebugEnabled();
126+
assertEquals(1, loggerUsage.size());
127+
AtomicInteger c = loggerUsage.get("isDebugEnabled");
128+
assertNotNull(c);
129+
assertEquals(1, c.get());
130+
assertEquals(1, uncaughtCount.get());
131+
} finally {
132+
LoggerAdapter.setLoggerFailureHandler(null);
133+
}
134+
}
135+
}

‎vertx-core/src/main/java/io/vertx/core/impl/TaskQueue.java‎

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -33,9 +33,10 @@
3333
*/
3434
public class TaskQueue {
3535

36-
static final Logger log = LoggerFactory.getLogger(TaskQueue.class);
36+
static final Logger LOGGER = LoggerFactory.getLogger(TaskQueue.class);
3737

3838
// @protectedby tasks
39+
private final Logger log;
3940
private final LinkedList<Task> tasks = new LinkedList<>();
4041
private final Set<ContinuationTask> continuations = new HashSet<>();
4142
private boolean closed;
@@ -45,10 +46,15 @@ public class TaskQueue {
4546

4647
private final Runnable runner;
4748

48-
public TaskQueue() {
49+
public TaskQueue(Logger log) {
50+
this.log = log;
4951
runner = this::run;
5052
}
5153

54+
public TaskQueue() {
55+
this(LOGGER);
56+
}
57+
5258
private void run() {
5359
for (; ; ) {
5460
final ExecuteTask execute;
@@ -79,7 +85,10 @@ private void run() {
7985
currentTask = execute;
8086
execute.runnable.run();
8187
} catch (Throwable t) {
82-
log.error("Caught unexpected Throwable", t);
88+
try {
89+
log.error("Caught unexpected Throwable", t);
90+
} catch (Throwable ignore) {
91+
}
8392
} finally {
8493
currentThread = null;
8594
currentTask = null;

0 commit comments

Comments
 (0)