diff --git a/trpc-core/src/main/java/com/tencent/trpc/core/common/timer/HashedWheelTimer.java b/trpc-core/src/main/java/com/tencent/trpc/core/common/timer/HashedWheelTimer.java index 522706b0e..6766c48d5 100644 --- a/trpc-core/src/main/java/com/tencent/trpc/core/common/timer/HashedWheelTimer.java +++ b/trpc-core/src/main/java/com/tencent/trpc/core/common/timer/HashedWheelTimer.java @@ -261,7 +261,7 @@ public HashedWheelTimer(ThreadFactory threadFactory, long tickDuration, TimeUnit } if (duration < MILLISECOND_NANOS) { - logger.warn("Configured tickDuration %d smaller then %d, using 1ms.", tickDuration, + logger.warn("Configured tickDuration {} smaller then {}, using 1ms.", tickDuration, MILLISECOND_NANOS); this.tickDuration = MILLISECOND_NANOS; } else { diff --git a/trpc-core/src/main/java/com/tencent/trpc/core/transport/AbstractClientTransport.java b/trpc-core/src/main/java/com/tencent/trpc/core/transport/AbstractClientTransport.java index 3c37a455d..22e9dd29e 100644 --- a/trpc-core/src/main/java/com/tencent/trpc/core/transport/AbstractClientTransport.java +++ b/trpc-core/src/main/java/com/tencent/trpc/core/transport/AbstractClientTransport.java @@ -178,10 +178,10 @@ public void close() { @Override public CompletionStage send(Object msg) throws TransportException { if (isClosed()) { - throw TransportException.create(String.format( + throw TransportException.create( "Client transport(transport=%s, class=%s, msg=%s) send fail, due to transport" + " is not available or close", - this, name, msg)); + this, name, msg); } return getChannel0().thenCompose(f -> f.send(msg)); } @@ -192,10 +192,10 @@ public CompletionStage send(Object msg) throws TransportException { @Override public CompletionStage getChannel() throws TransportException { if (isClosed()) { - throw TransportException.create(String.format( + throw TransportException.create( "Client transport(transport=%s, class=%s) get channel fail, due to transport " + "is not available or close", - this, name)); + this, name); } return getChannel0(); } @@ -419,8 +419,7 @@ protected void stopInternal() throws Exception { try { doClose(); } catch (Throwable ex) { - logger.error(String.format("Client transport(%s) destroy failed", getRemoteAddress(), - ex)); + logger.error(String.format("Client transport(%s) destroy failed", getRemoteAddress()), ex); } try { if (handler != null) { diff --git a/trpc-core/src/test/java/com/tencent/trpc/core/common/timer/HashWheelTimerTest.java b/trpc-core/src/test/java/com/tencent/trpc/core/common/timer/HashWheelTimerTest.java index 09ec6198a..b185a4c45 100644 --- a/trpc-core/src/test/java/com/tencent/trpc/core/common/timer/HashWheelTimerTest.java +++ b/trpc-core/src/test/java/com/tencent/trpc/core/common/timer/HashWheelTimerTest.java @@ -54,6 +54,54 @@ public void testInit() { hashedWheelTimer.stop(); } + /** + * A tick duration smaller than one millisecond is normalized to one millisecond and a warning is logged. The + * warning uses the {@code {}} placeholder of slf4j, a printf style placeholder would leave the raw text in the + * log and lose the real values. + */ + @Test + public void testTickDurationSmallerThanOneMillisecond() { + HashedWheelTimer hashedWheelTimer = new HashedWheelTimer(new NamedThreadFactory(), 1L, + TimeUnit.NANOSECONDS); + try { + Assert.assertNotNull(hashedWheelTimer); + hashedWheelTimer.start(); + // the tick duration has been normalized, so the timer still works + Timeout timeout = hashedWheelTimer.newTimeout(t -> { + }, 1000, TimeUnit.MILLISECONDS); + Assert.assertFalse(timeout.isExpired()); + timeout.cancel(); + } finally { + hashedWheelTimer.stop(); + } + } + + /** + * An illegal tick duration should be rejected. + */ + @Test + public void testIllegalTickDuration() { + try { + new HashedWheelTimer(new NamedThreadFactory(), 0L, TimeUnit.MILLISECONDS); + Assert.fail("IllegalArgumentException is expected"); + } catch (IllegalArgumentException e) { + Assert.assertTrue(e.getMessage(), e.getMessage().contains("tickDuration must be greater than 0")); + } + } + + /** + * A tick duration which overflows the wheel should be rejected. + */ + @Test + public void testTickDurationOverflow() { + try { + new HashedWheelTimer(new NamedThreadFactory(), Long.MAX_VALUE / 2, TimeUnit.DAYS); + Assert.fail("IllegalArgumentException is expected"); + } catch (IllegalArgumentException e) { + Assert.assertTrue(e.getMessage(), e.getMessage().contains("tickDuration")); + } + } + @Test public void test() { timer.toString(); diff --git a/trpc-core/src/test/java/com/tencent/trpc/core/exception/TransportExceptionTest.java b/trpc-core/src/test/java/com/tencent/trpc/core/exception/TransportExceptionTest.java new file mode 100644 index 000000000..f39a3a05b --- /dev/null +++ b/trpc-core/src/test/java/com/tencent/trpc/core/exception/TransportExceptionTest.java @@ -0,0 +1,138 @@ +/* + * Tencent is pleased to support the open source community by making tRPC available. + * + * Copyright (C) 2023 Tencent. + * All rights reserved. + * + * If you have downloaded a copy of the tRPC source code from Tencent, + * please note that tRPC source code is licensed under the Apache 2.0 License, + * A copy of the Apache 2.0 License can be found in the LICENSE file. + */ + +package com.tencent.trpc.core.exception; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertNull; +import static org.junit.Assert.assertSame; +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; + +import java.util.UnknownFormatConversionException; +import org.junit.Test; + +/** + * Test {@link TransportException}, especially the {@code create} methods which format the message by themselves, so + * the callers must pass the raw format and the arguments instead of an already formatted string. + */ +public class TransportExceptionTest { + + private static final String MESSAGE = "transport error"; + + @Test + public void testConstructWithMessage() { + TransportException e = new TransportException(MESSAGE); + assertEquals(MESSAGE, e.getMessage()); + assertNull(e.getCause()); + } + + @Test + public void testConstructWithMessageAndCause() { + IllegalStateException cause = new IllegalStateException("cause"); + TransportException e = new TransportException(MESSAGE, cause); + assertEquals(MESSAGE, e.getMessage()); + assertSame(cause, e.getCause()); + } + + @Test + public void testConstructWithCause() { + IllegalStateException cause = new IllegalStateException("cause"); + TransportException e = new TransportException(cause); + assertEquals("cause", e.getMessage()); + assertSame(cause, e.getCause()); + } + + @Test + public void testCreateFormatsArguments() { + TransportException e = TransportException.create("send fail, addr=%s, port=%s", "127.0.0.1", 8080); + assertEquals("send fail, addr=127.0.0.1, port=8080", e.getMessage()); + assertNull(e.getCause()); + } + + @Test + public void testCreateWithCauseFormatsArguments() { + IllegalStateException cause = new IllegalStateException("cause"); + TransportException e = TransportException.create(cause, "send fail, addr=%s", "127.0.0.1"); + assertEquals("send fail, addr=127.0.0.1", e.getMessage()); + assertSame(cause, e.getCause()); + } + + @Test + public void testCreateWithNullCauseFormatsArguments() { + TransportException e = TransportException.create((Throwable) null, "send fail, addr=%s", "127.0.0.1"); + assertEquals("send fail, addr=127.0.0.1", e.getMessage()); + assertNull(e.getCause()); + } + + @Test + public void testCreateWithoutArguments() { + TransportException e = TransportException.create("send fail"); + assertEquals("send fail", e.getMessage()); + } + + @Test + public void testCreateWithNullArgument() { + TransportException e = TransportException.create("send fail, msg=%s", (Object) null); + assertEquals("send fail, msg=null", e.getMessage()); + } + + /** + * The argument may contain a percent sign, and it must be kept as it is, because only the format is formatted. + */ + @Test + public void testCreateKeepsPercentSignOfArgument() { + TransportException e = TransportException.create("send fail, msg=%s", "GET /a%2Fb?rate=100%"); + assertEquals("send fail, msg=GET /a%2Fb?rate=100%", e.getMessage()); + } + + /** + * The caller must never pass an already formatted message which contains a percent sign, otherwise the message + * is formatted twice and the real error is hidden by a format exception. This test pins down the behaviour so + * that the double formatting can be caught. + */ + @Test + public void testCreateWithAlreadyFormattedMessageContainingPercentFails() { + String formatted = String.format("send fail, msg=%s", "GET /a%2Fb"); + assertEquals("send fail, msg=GET /a%2Fb", formatted); + try { + TransportException.create(formatted); + fail("UnknownFormatConversionException is expected"); + } catch (UnknownFormatConversionException e) { + assertNotNull(e.getMessage()); + } + } + + @Test + public void testTransReturnsTheSameInstanceForTransportException() { + TransportException origin = new TransportException(MESSAGE); + assertSame(origin, TransportException.trans(origin)); + assertSame(origin, TransportException.trans(origin, "other message")); + } + + @Test + public void testTransWrapsOtherException() { + IllegalStateException cause = new IllegalStateException("cause"); + TransportException e = TransportException.trans(cause); + assertEquals("cause", e.getMessage()); + assertSame(cause, e.getCause()); + + TransportException withMessage = TransportException.trans(cause, MESSAGE); + assertEquals(MESSAGE, withMessage.getMessage()); + assertSame(cause, withMessage.getCause()); + } + + @Test + public void testIsRuntimeException() { + assertTrue(new TransportException(MESSAGE) instanceof RuntimeException); + } +} diff --git a/trpc-core/src/test/java/com/tencent/trpc/core/logger/LogPlaceholderConventionTest.java b/trpc-core/src/test/java/com/tencent/trpc/core/logger/LogPlaceholderConventionTest.java new file mode 100644 index 000000000..15b19f1c0 --- /dev/null +++ b/trpc-core/src/test/java/com/tencent/trpc/core/logger/LogPlaceholderConventionTest.java @@ -0,0 +1,385 @@ +/* + * Tencent is pleased to support the open source community by making tRPC available. + * + * Copyright (C) 2023 Tencent. + * All rights reserved. + * + * If you have downloaded a copy of the tRPC source code from Tencent, + * please note that tRPC source code is licensed under the Apache 2.0 License, + * A copy of the Apache 2.0 License can be found in the LICENSE file. + */ + +package com.tencent.trpc.core.logger; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; + +import java.io.File; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.Paths; +import java.util.List; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import java.util.stream.Collectors; +import java.util.stream.Stream; +import org.junit.Test; + +/** + * Guard the log placeholder style of the whole repository. + * + *

The logger of the framework delegates to slf4j, which only recognizes the {@code {}} placeholder. A printf + * style placeholder(such as {@code %s} or {@code %d}) is never replaced by slf4j, so the real values are silently + * lost from the log. Besides, the number of the placeholders must match the number of the arguments, otherwise + * either an argument is dropped or a raw {@code {}} is left in the log message.

+ * + *

This test scans the production sources so that such defects can be found before they reach the production + * environment.

+ */ +public class LogPlaceholderConventionTest { + + /** + * The pattern of a logging call of the framework logger. + */ + private static final Pattern LOG_CALL = Pattern.compile( + "\\b(?:logger|LOG|log|LOGGER)\\s*\\.\\s*(?:error|warn|info|debug|trace)\\s*\\("); + + /** + * The pattern of a printf style placeholder, {@code %%} is excluded because it is an escaped percent sign. + */ + private static final Pattern PRINTF_PLACEHOLDER = Pattern.compile( + "%(?!%)[-#+ 0,(]*\\d*(?:\\.\\d+)?[sdifxXoeEgGbBhHnc]"); + + /** + * The pattern of a string literal. + */ + private static final Pattern STRING_LITERAL = Pattern.compile("\"((?:[^\"\\\\]|\\\\.)*)\""); + + /** + * The name of the variables which are very likely to be a throwable, a throwable is allowed to be the last + * argument of a logging call without a matching placeholder. + */ + private static final Pattern THROWABLE_LIKE = Pattern.compile( + "^(?:e|ex|t|th|err|error|cause|throwable|exception|ignored|ignore)\\d*$" + + "|(?:\\.getCause\\(\\)|\\.cause\\(\\))$"); + + /** + * The max number of the lines a logging call may span. + */ + private static final int MAX_CALL_LINES = 12; + + private static final String MAIN_SOURCE_DIR = "src/main/java"; + + @Test + public void testNoPrintfPlaceholderInLoggingCall() throws IOException { + List defects = scan(LogCall::hasPrintfPlaceholder, + "printf style placeholder is not supported by slf4j, use {} instead"); + assertTrue(String.join("\n", defects), defects.isEmpty()); + } + + @Test + public void testPlaceholderCountMatchesArgumentCount() throws IOException { + List defects = scan(LogCall::hasMismatchedPlaceholder, + "the number of the placeholders does not match the number of the arguments"); + assertTrue(String.join("\n", defects), defects.isEmpty()); + } + + /** + * Make sure the scanner really works, otherwise the two test cases above would pass silently even if the + * scanner is broken. + */ + @Test + public void testScannerDetectsPrintfPlaceholder() { + LogCall call = LogCall.of("\"Configured tickDuration %d smaller then %d, using 1ms.\", a, b"); + assertTrue(call.hasPrintfPlaceholder()); + assertFalse(LogCall.of("\"Configured tickDuration {} smaller then {}\", a, b").hasPrintfPlaceholder()); + // a percent sign of a plain text is not a placeholder + assertFalse(LogCall.of("\"progress is 100%\"").hasPrintfPlaceholder()); + } + + @Test + public void testScannerDetectsMismatchedPlaceholder() { + assertTrue(LogCall.of("\"request {}, basePath is {}\", path").hasMismatchedPlaceholder()); + assertTrue(LogCall.of("\"request {}\", path, basePath").hasMismatchedPlaceholder()); + assertFalse(LogCall.of("\"request {}, basePath is {}\", path, basePath").hasMismatchedPlaceholder()); + // a throwable is allowed to be the last argument without a placeholder + assertFalse(LogCall.of("\"request {} failed\", path, e").hasMismatchedPlaceholder()); + assertFalse(LogCall.of("\"request failed\", e").hasMismatchedPlaceholder()); + // the string is built by concatenation, there is no placeholder at all + assertFalse(LogCall.of("\"request \" + path + \" failed\", e").hasMismatchedPlaceholder()); + } + + @Test + public void testScannerSkipsStringFormat() { + // String.format uses the printf style, it is the caller of the logger that formats the message + assertFalse(LogCall.of("String.format(\"request %s failed\", path), e").hasPrintfPlaceholder()); + } + + private List scan(java.util.function.Predicate predicate, String reason) throws IOException { + Path root = findRepositoryRoot(); + try (Stream stream = Files.walk(root)) { + List sources = stream + .filter(Files::isRegularFile) + .filter(p -> p.toString().endsWith(".java")) + .filter(p -> p.toString().replace(File.separatorChar, '/').contains(MAIN_SOURCE_DIR)) + .collect(Collectors.toList()); + return sources.stream() + .flatMap(p -> scanFile(p, predicate, reason).stream()) + .collect(Collectors.toList()); + } + } + + private List scanFile(Path path, java.util.function.Predicate predicate, String reason) { + List defects = new java.util.ArrayList<>(); + List lines; + try { + lines = Files.readAllLines(path); + } catch (IOException e) { + return defects; + } + for (int i = 0; i < lines.size(); i++) { + if (!LOG_CALL.matcher(lines.get(i)).find()) { + continue; + } + String arguments = extractArguments(lines, i); + if (arguments == null) { + continue; + } + LogCall call = LogCall.of(arguments); + if (predicate.test(call)) { + defects.add(String.format("%s:%d: %s%n %s", path, i + 1, reason, + arguments.replaceAll("\\s+", " "))); + } + } + return defects; + } + + /** + * Extract the argument list of the logging call which starts at the given line. + * + * @param lines all the lines of the source file + * @param begin the index of the line the logging call starts at + * @return the argument list without the enclosing parentheses, or null if it can not be extracted + */ + private String extractArguments(List lines, int begin) { + StringBuilder buffer = new StringBuilder(); + for (int i = begin; i < Math.min(begin + MAX_CALL_LINES, lines.size()); i++) { + buffer.append(lines.get(i)).append(' '); + Matcher matcher = LOG_CALL.matcher(buffer); + if (!matcher.find()) { + continue; + } + String arguments = readUntilClosed(buffer.substring(matcher.end())); + if (arguments != null) { + return arguments; + } + } + return null; + } + + /** + * Read the content until the parenthesis of the logging call is closed. + * + * @param text the text just after the opening parenthesis + * @return the content of the parentheses, or null if the parenthesis is not closed yet + */ + private static String readUntilClosed(String text) { + StringBuilder result = new StringBuilder(); + int depth = 1; + boolean inString = false; + boolean escaped = false; + for (char c : text.toCharArray()) { + if (escaped) { + result.append(c); + escaped = false; + continue; + } + if (c == '\\') { + result.append(c); + escaped = true; + continue; + } + if (c == '"') { + inString = !inString; + result.append(c); + continue; + } + if (!inString) { + if (c == '(') { + depth++; + } else if (c == ')') { + depth--; + if (depth == 0) { + return result.toString(); + } + } + } + result.append(c); + } + return null; + } + + private Path findRepositoryRoot() { + Path current = Paths.get("").toAbsolutePath(); + while (current != null && !Files.exists(current.resolve("trpc-core"))) { + current = current.getParent(); + } + return current == null ? Paths.get("").toAbsolutePath() : current; + } + + /** + * A parsed logging call. + */ + private static final class LogCall { + + private final String arguments; + + private final List topLevelArguments; + + private LogCall(String arguments) { + this.arguments = arguments; + this.topLevelArguments = splitTopLevel(arguments); + } + + static LogCall of(String arguments) { + return new LogCall(arguments); + } + + /** + * Whether the message contains a printf style placeholder while it is not formatted by String.format. + * + * @return true if the logging call is defective + */ + boolean hasPrintfPlaceholder() { + if (arguments.contains("String.format")) { + return false; + } + if (topLevelArguments.size() < 2) { + // without any argument the percent sign is only a part of the plain text + return false; + } + return PRINTF_PLACEHOLDER.matcher(literalOf(firstArgument())).find(); + } + + /** + * Whether the number of the placeholders does not match the number of the arguments. + * + * @return true if the logging call is defective + */ + boolean hasMismatchedPlaceholder() { + String first = firstArgument(); + if (!first.contains("\"") || arguments.contains("String.format")) { + return false; + } + if (first.contains("+")) { + // the message is built by concatenation, the braces of the literals are not placeholders, and the + // values are already embedded in the message + return false; + } + int placeholders = countOccurrences(literalOf(first)); + List rest = topLevelArguments.subList(1, topLevelArguments.size()); + int arguments = rest.size(); + boolean lastIsThrowable = !rest.isEmpty() + && THROWABLE_LIKE.matcher(rest.get(rest.size() - 1).trim()).find(); + return placeholders != arguments && placeholders != arguments - (lastIsThrowable ? 1 : 0); + } + + private String firstArgument() { + return topLevelArguments.isEmpty() ? "" : topLevelArguments.get(0); + } + + /** + * Concatenate all the string literals of the given text, the concatenated literals form the log message. + * + * @param text the text to be parsed + * @return the concatenated string literals + */ + private static String literalOf(String text) { + StringBuilder builder = new StringBuilder(); + Matcher matcher = STRING_LITERAL.matcher(text); + while (matcher.find()) { + builder.append(matcher.group(1)); + } + return builder.toString(); + } + + private static int countOccurrences(String literal) { + int count = 0; + int index = literal.indexOf("{}"); + while (index >= 0) { + count++; + index = literal.indexOf("{}", index + 2); + } + return count; + } + + /** + * Split the argument list by the top level commas, the commas inside a string, a parenthesis, a bracket or a + * brace are ignored. + * + * @param text the argument list + * @return the top level arguments + */ + private static List splitTopLevel(String text) { + List result = new java.util.ArrayList<>(); + StringBuilder current = new StringBuilder(); + int depth = 0; + boolean inString = false; + boolean inChar = false; + boolean escaped = false; + for (char c : text.toCharArray()) { + if (escaped) { + current.append(c); + escaped = false; + continue; + } + if (c == '\\') { + current.append(c); + escaped = true; + continue; + } + if (c == '\'' && !inString) { + inChar = !inChar; + current.append(c); + continue; + } + if (c == '"' && !inChar) { + inString = !inString; + current.append(c); + continue; + } + if (inString || inChar) { + current.append(c); + continue; + } + if (c == '(' || c == '[' || c == '{') { + depth++; + } else if (c == ')' || c == ']' || c == '}') { + depth--; + } + if (c == ',' && depth == 0) { + result.add(current.toString().trim()); + current.setLength(0); + continue; + } + current.append(c); + } + String last = current.toString().trim(); + if (!last.isEmpty() || !result.isEmpty()) { + result.add(last); + } + return result; + } + } + + /** + * Make sure the constant is used, it also documents the expected placeholder style. + */ + @Test + public void testPlaceholderStyle() { + assertEquals(2, LogCall.countOccurrences("a={}, b={}")); + assertEquals(0, LogCall.countOccurrences("a=%s")); + } +} diff --git a/trpc-core/src/test/java/com/tencent/trpc/core/transport/AbstractClientTransportTest.java b/trpc-core/src/test/java/com/tencent/trpc/core/transport/AbstractClientTransportTest.java index 4ff645024..620f7eff9 100644 --- a/trpc-core/src/test/java/com/tencent/trpc/core/transport/AbstractClientTransportTest.java +++ b/trpc-core/src/test/java/com/tencent/trpc/core/transport/AbstractClientTransportTest.java @@ -11,17 +11,29 @@ package com.tencent.trpc.core.transport; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; import com.tencent.trpc.core.common.config.ProtocolConfig; import com.tencent.trpc.core.exception.TransportException; import com.tencent.trpc.core.transport.codec.ClientCodec; +import java.net.InetSocketAddress; import java.util.Set; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CompletionStage; import org.junit.Test; public class AbstractClientTransportTest { + /** + * A message whose toString contains the format specifier characters, it is used to make sure the error message + * is formatted only once. + */ + private static final String MSG_WITH_PERCENT = "GET /a%2Fb?rate=100%"; + @Test public void testOpenException() throws Exception { ClientTransportTest test = new ClientTransportTest(TransporterTestUtils.newProtocolConfig(), @@ -51,16 +63,193 @@ public void testOpenException() throws Exception { test2.toString(); } + /** + * The error message of a closed transport should carry the transport, the class and the message, and the format + * specifiers must be replaced by the real arguments. + */ + @Test + public void testSendAfterClosedThrowsFormattedException() throws Exception { + ClientTransportTest transport = newClosedTransport(); + try { + transport.send("hello"); + fail("TransportException is expected"); + } catch (TransportException e) { + String message = e.getMessage(); + assertNotNull(message); + assertNull(e.getCause()); + assertTrue(message, message.contains(transport.toString())); + assertTrue(message, message.contains(ClientTransportTest.class.getName())); + assertTrue(message, message.contains("hello")); + assertTrue(message, message.contains("send fail")); + // all the format specifiers have been replaced + assertTrue(message, !message.contains("%s")); + } + } + + /** + * The message to be sent is untrusted, it may contain a percent sign. Formatting the error message twice would + * throw a format exception and hide the real error, so it must be formatted only once. + */ + @Test + public void testSendAfterClosedWithPercentInMessage() throws Exception { + ClientTransportTest transport = newClosedTransport(); + try { + transport.send(MSG_WITH_PERCENT); + fail("TransportException is expected"); + } catch (TransportException e) { + assertTrue(e.getMessage(), e.getMessage().contains(MSG_WITH_PERCENT)); + } + } + + /** + * The transport itself may also contain a percent sign, for example the remote address of a unix domain socket. + */ + @Test + public void testSendAfterClosedWithPercentInTransport() throws Exception { + ClientTransportTest transport = newClosedTransport(); + transport.setDescription("transport-100%-desc"); + try { + transport.send("hello"); + fail("TransportException is expected"); + } catch (TransportException e) { + assertTrue(e.getMessage(), e.getMessage().contains("transport-100%-desc")); + } + } + + @Test + public void testGetChannelAfterClosedThrowsFormattedException() throws Exception { + ClientTransportTest transport = newClosedTransport(); + transport.setDescription("transport-100%-desc"); + try { + transport.getChannel(); + fail("TransportException is expected"); + } catch (TransportException e) { + String message = e.getMessage(); + assertNotNull(message); + assertNull(e.getCause()); + assertTrue(message, message.contains("transport-100%-desc")); + assertTrue(message, message.contains(ClientTransportTest.class.getName())); + assertTrue(message, message.contains("get channel fail")); + assertTrue(message, !message.contains("%s")); + } + } + + /** + * A null message must not break the error message building. + */ + @Test + public void testSendAfterClosedWithNullMessage() throws Exception { + ClientTransportTest transport = newClosedTransport(); + try { + transport.send(null); + fail("TransportException is expected"); + } catch (TransportException e) { + assertTrue(e.getMessage(), e.getMessage().contains("msg=null")); + } + } + + /** + * When a channel fails to be closed, the error should be logged with the channel item and the cause, and the + * remaining steps(doClose and the handler destroying) should still be executed. + * + *

The lifecycle only executes stopInternal when it has left the new state, so the transport is opened first. + * The open fails on purpose so that the state becomes FAILED, and then stop executes stopInternal.

+ */ + @Test + public void testCloseLogsChannelCloseFailure() throws Exception { + ClientTransportTest transport = new ClientTransportTest(TransporterTestUtils.newProtocolConfig(), + new ThrowingDestroyChannelHandler(), TransporterTestUtils.newClientCodec(), true); + transport.channels.add(new AbstractClientTransport.ChannelFutureItem( + CompletableFuture.completedFuture(new ThrowingCloseChannel()), + TransporterTestUtils.newProtocolConfig())); + try { + // the open fails, and the failed start triggers the stop which executes stopInternal + transport.open(); + fail("TransportException is expected"); + } catch (TransportException e) { + assertNotNull(e.getMessage()); + } + assertTrue(transport.isClosed()); + // the channel close, the doClose and the handler destroying all failed, but they were all attempted + assertTrue(transport.isDoCloseCalled()); + } + + private ClientTransportTest newClosedTransport() throws Exception { + ClientTransportTest transport = new ClientTransportTest(TransporterTestUtils.newProtocolConfig(), + TransporterTestUtils.newChannelHandler(), TransporterTestUtils.newClientCodec(), true); + transport.close(); + assertTrue(transport.isClosed()); + return transport; + } + + /** + * A channel whose close always fails, it is used to trigger the error log of the channel closing. + */ + private static class ThrowingCloseChannel implements Channel { + + @Override + public CompletionStage close() { + throw new IllegalStateException("close failed"); + } + + @Override + public CompletionStage send(Object message) { + return CompletableFuture.completedFuture(null); + } + + @Override + public boolean isClosed() { + return false; + } + + @Override + public boolean isConnected() { + return true; + } + + @Override + public InetSocketAddress getRemoteAddress() { + return new InetSocketAddress("127.0.0.1", 6666); + } + + @Override + public InetSocketAddress getLocalAddress() { + return new InetSocketAddress("127.0.0.1", 6667); + } + + @Override + public ProtocolConfig getProtocolConfig() { + return TransporterTestUtils.newProtocolConfig(); + } + } + private static class ClientTransportTest extends AbstractClientTransport { private boolean isTransportException; + private String description; + + private boolean doCloseCalled; + ClientTransportTest(ProtocolConfig config, ChannelHandler channelHandler, ClientCodec clientCodec, boolean isTransportException) throws TransportException { super(config, channelHandler, clientCodec); this.isTransportException = isTransportException; } + void setDescription(String description) { + this.description = description; + } + + boolean isDoCloseCalled() { + return doCloseCalled; + } + + @Override + public String toString() { + return description == null ? super.toString() : description; + } + @Override public Set getChannels() { return null; @@ -82,6 +271,7 @@ protected CompletableFuture make() throws Exception { @Override protected void doClose() { + doCloseCalled = true; throw new IllegalArgumentException(); } @@ -91,4 +281,36 @@ protected boolean useChannelPool() { } } + + /** + * A channel handler whose destroying always fails, it is used to trigger the error log of the handler + * destroying. + */ + private static class ThrowingDestroyChannelHandler implements ChannelHandler { + + @Override + public void connected(Channel channel) { + } + + @Override + public void disconnected(Channel channel) { + } + + @Override + public void send(Channel channel, Object message) { + } + + @Override + public void received(Channel channel, Object message) { + } + + @Override + public void caught(Channel channel, Throwable exception) { + } + + @Override + public void destroy() { + throw new IllegalStateException("destroy failed"); + } + } } diff --git a/trpc-spring-support/trpc-springmvc/src/main/java/com/tencent/trpc/springmvc/TRpcServiceHandlerMapping.java b/trpc-spring-support/trpc-springmvc/src/main/java/com/tencent/trpc/springmvc/TRpcServiceHandlerMapping.java index b492a936a..807516f5e 100644 --- a/trpc-spring-support/trpc-springmvc/src/main/java/com/tencent/trpc/springmvc/TRpcServiceHandlerMapping.java +++ b/trpc-spring-support/trpc-springmvc/src/main/java/com/tencent/trpc/springmvc/TRpcServiceHandlerMapping.java @@ -89,7 +89,7 @@ public void onApplicationEvent(ContextRefreshedEvent event) { @Override protected RpcMethodInfoAndInvoker getHandlerInternal(HttpServletRequest request) { String requestPath = request.getRequestURI(); - logger.debug("got trpc springmvc request {}, basePath is {}", requestPath); + logger.debug("got trpc springmvc request {}", requestPath); String method = request.getMethod(); if (!TRpcHttpConstants.HTTP_METHOD_GET.equals(method) && !TRpcHttpConstants.HTTP_METHOD_POST.equals(method)) {